From 8541f6adcd7e5ba1d035dd314004f4fc3e9a35e0 Mon Sep 17 00:00:00 2001 From: Martyn Inglis Date: Tue, 13 Sep 2016 12:29:40 +0100 Subject: [PATCH 1/4] Change DAO to return the notification from an update, not Boolean - tests reflect this --- app/dao/notifications_dao.py | 6 +++--- tests/app/dao/test_notification_dao.py | 30 ++++++++++++++++++++++---- 2 files changed, 29 insertions(+), 7 deletions(-) diff --git a/app/dao/notifications_dao.py b/app/dao/notifications_dao.py index aaab8f5e2..d6346750b 100644 --- a/app/dao/notifications_dao.py +++ b/app/dao/notifications_dao.py @@ -139,7 +139,7 @@ def _update_notification_status(notification, status): status = _decide_permanent_temporary_failure(current_status=notification.status, status=status) notification.status = status dao_update_notification(notification) - return True + return notification @statsd(namespace="dao") @@ -152,7 +152,7 @@ def update_notification_status_by_id(notification_id, status): Notification.status == 'pending')).first() if not notification: - return False + return None return _update_notification_status( notification=notification, @@ -169,7 +169,7 @@ def update_notification_status_by_reference(reference, status): Notification.status == 'pending')).first() if not notification: - return False + return None return _update_notification_status( notification=notification, diff --git a/tests/app/dao/test_notification_dao.py b/tests/app/dao/test_notification_dao.py index 3ef686713..2a64e071a 100644 --- a/tests/app/dao/test_notification_dao.py +++ b/tests/app/dao/test_notification_dao.py @@ -236,7 +236,8 @@ def test_should_by_able_to_update_status_by_reference(sample_email_template, ses notification.reference = 'reference' dao_update_notification(notification) - update_notification_status_by_reference('reference', 'delivered') + updated = update_notification_status_by_reference('reference', 'delivered') + assert updated.status == 'delivered' assert Notification.query.get(notification.id).status == 'delivered' @@ -249,8 +250,10 @@ def test_should_by_able_to_update_status_by_id(sample_template, sample_job, mmg_ assert Notification.query.get(notification.id).status == 'sending' with freeze_time('2000-01-02 12:00:00'): - assert update_notification_status_by_id(notification.id, 'delivered') + updated = update_notification_status_by_id(notification.id, 'delivered') + assert updated.status == 'delivered' + assert updated.updated_at == datetime(2000, 1, 2, 12, 0, 0) assert Notification.query.get(notification.id).status == 'delivered' assert notification.updated_at == datetime(2000, 1, 2, 12, 0, 0) @@ -264,10 +267,29 @@ def test_should_not_update_status_by_id_if_not_sending_and_does_not_update_job(n assert job == Job.query.get(notification.job_id) -def test_should_update_status_if_created(notify_db, notify_db_session): +def test_should_not_update_status_by_reference_if_not_sending_and_does_not_update_job(notify_db, notify_db_session): + notification = sample_notification(notify_db, notify_db_session, status='delivered', reference='reference') + job = Job.query.get(notification.job_id) + assert Notification.query.get(notification.id).status == 'delivered' + assert not update_notification_status_by_reference('reference', 'failed') + assert Notification.query.get(notification.id).status == 'delivered' + assert job == Job.query.get(notification.job_id) + + +def test_should_update_status_by_id_if_created(notify_db, notify_db_session): notification = sample_notification(notify_db, notify_db_session, status='created') assert Notification.query.get(notification.id).status == 'created' - assert update_notification_status_by_id(notification.id, 'failed') + updated = update_notification_status_by_id(notification.id, 'failed') + assert Notification.query.get(notification.id).status == 'failed' + assert updated.status == 'failed' + + +def test_should_not_update_status_by_reference_if_not_sending(notify_db, notify_db_session): + notification = sample_notification(notify_db, notify_db_session, status='created', reference='reference') + assert Notification.query.get(notification.id).status == 'created' + updated = update_notification_status_by_reference('reference', 'failed') + assert Notification.query.get(notification.id).status == 'created' + assert not updated def test_should_by_able_to_update_status_by_id_from_pending_to_delivered(sample_template, sample_job): From 517cec173b6e80ca2f54227287247d327d2daaf2 Mon Sep 17 00:00:00 2001 From: Martyn Inglis Date: Tue, 13 Sep 2016 13:04:44 +0100 Subject: [PATCH 2/4] Logs time between sent_at and the provider callback into statsd --- app/notifications/process_client_response.py | 9 +- app/notifications/rest.py | 28 ++--- tests/app/conftest.py | 2 + .../app/notifications/rest/test_callbacks.py | 109 +++++++++++------- 4 files changed, 95 insertions(+), 53 deletions(-) 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'): From 1a4b303c4369d1adad46a47b96a3b436df4b9db1 Mon Sep 17 00:00:00 2001 From: Martyn Inglis Date: Tue, 13 Sep 2016 13:57:06 +0100 Subject: [PATCH 3/4] Only record the elapsed time at provider for notifications with a sent_at date, could be that have a problem with state, misaligned tasks, we should just not record as edge case and this is aggregate. --- app/clients/statsd/statsd_client.py | 5 + app/notifications/process_client_response.py | 10 +- app/notifications/rest.py | 27 +-- .../app/notifications/rest/test_callbacks.py | 169 ++++++++++++------ 4 files changed, 141 insertions(+), 70 deletions(-) diff --git a/app/clients/statsd/statsd_client.py b/app/clients/statsd/statsd_client.py index 19e89557e..cc404b8b5 100644 --- a/app/clients/statsd/statsd_client.py +++ b/app/clients/statsd/statsd_client.py @@ -24,3 +24,8 @@ class StatsdClient(StatsClient): def timing(self, stat, delta, rate=1): if self.active: super(StatsClient, self).timing(self.format_stat_name(stat), delta, rate) + + def timing_with_dates(self, stat, start, end, rate=1): + if self.active: + delta = (start - end).total_seconds() * 1000 + super(StatsClient, self).timing(stat, delta, rate) diff --git a/app/notifications/process_client_response.py b/app/notifications/process_client_response.py index edd152165..a586a52f3 100644 --- a/app/notifications/process_client_response.py +++ b/app/notifications/process_client_response.py @@ -71,9 +71,11 @@ 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) - ) + if notification.sent_at: + statsd_client.timing_with_dates( + '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 fa8463c68..99be6b0b2 100644 --- a/app/notifications/rest.py +++ b/app/notifications/rest.py @@ -97,7 +97,12 @@ def process_ses_response(): ) statsd_client.incr('callback.ses.{}'.format(notification_status)) - statsd_client.timing('callback.ses.elapsed-time', (datetime.utcnow() - notification.sent_at)) + if notification.sent_at: + statsd_client.timing_with_dates( + 'callback.ses.elapsed-time'.format(client_name.lower()), + datetime.utcnow(), + notification.sent_at + ) return jsonify( result="success", message="SES callback succeeded" ), 200 @@ -233,8 +238,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) @@ -242,14 +247,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/notifications/rest/test_callbacks.py b/tests/app/notifications/rest/test_callbacks.py index 6ec67e97f..eac7aa477 100644 --- a/tests/app/notifications/rest/test_callbacks.py +++ b/tests/app/notifications/rest/test_callbacks.py @@ -142,17 +142,28 @@ def test_firetext_callback_should_return_404_if_cannot_find_notification_id( ) -def test_firetext_callback_should_update_notification_status(notify_api, sample_notification, mocker): +def test_firetext_callback_should_update_notification_status( + notify_db, notify_db_session, notify_api, sample_email_template, mocker +): with notify_api.test_request_context(): with notify_api.test_client() as client: mocker.patch('app.statsd_client.incr') - original = get_notification_by_id(sample_notification.id) - assert original.status == 'created' + + notification = create_sample_notification( + notify_db, + notify_db_session, + template=sample_email_template, + reference='ref', + status='sending', + sent_at=datetime.utcnow()) + + original = get_notification_by_id(notification.id) + assert original.status == 'sending' response = client.post( path='/notifications/sms/firetext', data='mobile=441234123123&status=0&time=2016-03-10 14:17:00&reference={}'.format( - sample_notification.id + notification.id ), headers=[('Content-Type', 'application/x-www-form-urlencoded')]) @@ -160,24 +171,35 @@ def test_firetext_callback_should_update_notification_status(notify_api, sample_ assert response.status_code == 200 assert json_resp['result'] == 'success' assert json_resp['message'] == 'Firetext callback succeeded. reference {} updated'.format( - sample_notification.id + notification.id ) - updated = get_notification_by_id(sample_notification.id) + updated = get_notification_by_id(notification.id) assert updated.status == 'delivered' - assert get_notification_by_id(sample_notification.id).status == 'delivered' + assert get_notification_by_id(notification.id).status == 'delivered' -def test_firetext_callback_should_update_notification_status_failed(notify_api, sample_notification, mocker): +def test_firetext_callback_should_update_notification_status_failed( + notify_db, notify_db_session, notify_api, sample_template, mocker +): with notify_api.test_request_context(): with notify_api.test_client() as client: mocker.patch('app.statsd_client.incr') - original = get_notification_by_id(sample_notification.id) - assert original.status == 'created' + + notification = create_sample_notification( + notify_db, + notify_db_session, + template=sample_template, + reference='ref', + status='sending', + sent_at=datetime.utcnow()) + + original = get_notification_by_id(notification.id) + assert original.status == 'sending' response = client.post( path='/notifications/sms/firetext', data='mobile=441234123123&status=1&time=2016-03-10 14:17:00&reference={}'.format( - sample_notification.id + notification.id ), headers=[('Content-Type', 'application/x-www-form-urlencoded')]) @@ -185,16 +207,18 @@ def test_firetext_callback_should_update_notification_status_failed(notify_api, assert response.status_code == 200 assert json_resp['result'] == 'success' assert json_resp['message'] == 'Firetext callback succeeded. reference {} updated'.format( - sample_notification.id + notification.id ) - assert get_notification_by_id(sample_notification.id).status == 'permanent-failure' + assert get_notification_by_id(notification.id).status == 'permanent-failure' def test_firetext_callback_should_update_notification_status_pending(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') + notification = create_sample_notification( + notify_db, notify_db_session, status='sending', sent_at=datetime.utcnow() + ) original = get_notification_by_id(notification.id) assert original.status == 'sending' @@ -223,9 +247,15 @@ def test_firetext_callback_should_update_multiple_notification_status_sent( with notify_api.test_request_context(): with notify_api.test_client() as client: mocker.patch('app.statsd_client.incr') - notification1 = create_sample_notification(notify_db, notify_db_session, status='sending') - notification2 = create_sample_notification(notify_db, notify_db_session, status='sending') - notification3 = create_sample_notification(notify_db, notify_db_session, status='sending') + notification1 = create_sample_notification( + notify_db, notify_db_session, status='sending', sent_at=datetime.utcnow() + ) + notification2 = create_sample_notification( + notify_db, notify_db_session, status='sending', sent_at=datetime.utcnow() + ) + notification3 = create_sample_notification( + notify_db, notify_db_session, status='sending', sent_at=datetime.utcnow() + ) client.post( path='/notifications/sms/firetext', @@ -264,10 +294,15 @@ def test_process_mmg_response_return_200_when_cid_is_send_sms_code(notify_api): assert json_data['message'] == 'MMG callback succeeded: send-sms-code' -def test_process_mmg_response_returns_200_when_cid_is_valid_notification_id(notify_api, sample_notification): +def test_process_mmg_response_returns_200_when_cid_is_valid_notification_id( + notify_db, notify_db_session, notify_api +): with notify_api.test_client() as client: + notification = create_sample_notification( + notify_db, notify_db_session, status='sending', sent_at=datetime.utcnow() + ) data = json.dumps({"reference": "mmg_reference", - "CID": str(sample_notification.id), + "CID": str(notification.id), "MSISDN": "447777349060", "status": "3", "deliverytime": "2016-04-05 16:01:07"}) @@ -278,15 +313,20 @@ def test_process_mmg_response_returns_200_when_cid_is_valid_notification_id(noti assert response.status_code == 200 json_data = json.loads(response.data) assert json_data['result'] == 'success' - assert json_data['message'] == 'MMG callback succeeded. reference {} updated'.format(sample_notification.id) - assert get_notification_by_id(sample_notification.id).status == 'delivered' + assert json_data['message'] == 'MMG callback succeeded. reference {} updated'.format(notification.id) + assert get_notification_by_id(notification.id).status == 'delivered' -def test_process_mmg_response_status_5_updates_notification_with_permanently_failed(notify_api, - sample_notification): +def test_process_mmg_response_status_5_updates_notification_with_permanently_failed( + notify_db, notify_db_session, notify_api +): with notify_api.test_client() as client: + notification = create_sample_notification( + notify_db, notify_db_session, status='sending', sent_at=datetime.utcnow() + ) + data = json.dumps({"reference": "mmg_reference", - "CID": str(sample_notification.id), + "CID": str(notification.id), "MSISDN": "447777349060", "status": 5}) @@ -296,15 +336,19 @@ def test_process_mmg_response_status_5_updates_notification_with_permanently_fai assert response.status_code == 200 json_data = json.loads(response.data) assert json_data['result'] == 'success' - assert json_data['message'] == 'MMG callback succeeded. reference {} updated'.format(sample_notification.id) - assert get_notification_by_id(sample_notification.id).status == 'permanent-failure' + assert json_data['message'] == 'MMG callback succeeded. reference {} updated'.format(notification.id) + assert get_notification_by_id(notification.id).status == 'permanent-failure' -def test_process_mmg_response_status_2_updates_notification_with_permanently_failed(notify_api, - sample_notification): +def test_process_mmg_response_status_2_updates_notification_with_permanently_failed( + notify_db, notify_db_session, notify_api +): with notify_api.test_client() as client: + notification = create_sample_notification( + notify_db, notify_db_session, status='sending', sent_at=datetime.utcnow() + ) data = json.dumps({"reference": "mmg_reference", - "CID": str(sample_notification.id), + "CID": str(notification.id), "MSISDN": "447777349060", "status": 2}) @@ -314,15 +358,20 @@ def test_process_mmg_response_status_2_updates_notification_with_permanently_fai assert response.status_code == 200 json_data = json.loads(response.data) assert json_data['result'] == 'success' - assert json_data['message'] == 'MMG callback succeeded. reference {} updated'.format(sample_notification.id) - assert get_notification_by_id(sample_notification.id).status == 'permanent-failure' + assert json_data['message'] == 'MMG callback succeeded. reference {} updated'.format(notification.id) + assert get_notification_by_id(notification.id).status == 'permanent-failure' -def test_process_mmg_response_status_4_updates_notification_with_temporary_failed(notify_api, - sample_notification): +def test_process_mmg_response_status_4_updates_notification_with_temporary_failed( + notify_db, notify_db_session, notify_api +): with notify_api.test_client() as client: + notification = create_sample_notification( + notify_db, notify_db_session, status='sending', sent_at=datetime.utcnow() + ) + data = json.dumps({"reference": "mmg_reference", - "CID": str(sample_notification.id), + "CID": str(notification.id), "MSISDN": "447777349060", "status": 4}) @@ -332,15 +381,20 @@ def test_process_mmg_response_status_4_updates_notification_with_temporary_faile assert response.status_code == 200 json_data = json.loads(response.data) assert json_data['result'] == 'success' - assert json_data['message'] == 'MMG callback succeeded. reference {} updated'.format(sample_notification.id) - assert get_notification_by_id(sample_notification.id).status == 'temporary-failure' + assert json_data['message'] == 'MMG callback succeeded. reference {} updated'.format(notification.id) + assert get_notification_by_id(notification.id).status == 'temporary-failure' -def test_process_mmg_response_unknown_status_updates_notification_with_failed(notify_api, - sample_notification): +def test_process_mmg_response_unknown_status_updates_notification_with_failed( + notify_db, notify_db_session, notify_api +): with notify_api.test_client() as client: + + notification = create_sample_notification( + notify_db, notify_db_session, status='sending', sent_at=datetime.utcnow() + ) data = json.dumps({"reference": "mmg_reference", - "CID": str(sample_notification.id), + "CID": str(notification.id), "MSISDN": "447777349060", "status": 10}) @@ -350,8 +404,8 @@ def test_process_mmg_response_unknown_status_updates_notification_with_failed(no assert response.status_code == 200 json_data = json.loads(response.data) assert json_data['result'] == 'success' - assert json_data['message'] == 'MMG callback succeeded. reference {} updated'.format(sample_notification.id) - assert get_notification_by_id(sample_notification.id).status == 'failed' + assert json_data['message'] == 'MMG callback succeeded. reference {} updated'.format(notification.id) + assert get_notification_by_id(notification.id).status == 'failed' def test_process_mmg_response_returns_400_for_malformed_data(notify_api): @@ -450,7 +504,7 @@ def test_ses_callback_should_update_notification_status( with notify_api.test_client() as client: with freeze_time('2001-01-01T12:00:00'): mocker.patch('app.statsd_client.incr') - mocker.patch('app.statsd_client.timing') + mocker.patch('app.statsd_client.timing_with_dates') notification = create_sample_notification( notify_db, notify_db_session, @@ -472,8 +526,8 @@ def test_ses_callback_should_update_notification_status( 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.timing_with_dates.assert_any_call( + "callback.ses.elapsed-time", datetime.utcnow(), notification.sent_at ) app.statsd_client.incr.assert_any_call("callback.ses.delivered") @@ -491,6 +545,7 @@ def test_ses_callback_should_update_multiple_notification_status_sent( notify_db_session, template=sample_email_template, reference='ref1', + sent_at=datetime.utcnow(), status='sending') notification2 = create_sample_notification( @@ -498,6 +553,7 @@ def test_ses_callback_should_update_multiple_notification_status_sent( notify_db_session, template=sample_email_template, reference='ref2', + sent_at=datetime.utcnow(), status='sending') notification3 = create_sample_notification( @@ -505,6 +561,7 @@ def test_ses_callback_should_update_multiple_notification_status_sent( notify_db_session, template=sample_email_template, reference='ref3', + sent_at=datetime.utcnow(), status='sending') resp1 = client.post( @@ -539,9 +596,9 @@ def test_ses_callback_should_set_status_to_temporary_failure(notify_api, notify_db_session, template=sample_email_template, reference='ref', - status='sending' + status='sending', + sent_at=datetime.utcnow() ) - assert get_notification_by_id(notification.id).status == 'sending' response = client.post( @@ -567,7 +624,8 @@ def test_ses_callback_should_not_set_status_once_status_is_delivered(notify_api, notify_db_session, template=sample_email_template, reference='ref', - status='delivered' + status='delivered', + sent_at=datetime.utcnow() ) assert get_notification_by_id(notification.id).status == 'delivered' @@ -595,7 +653,8 @@ def test_ses_callback_should_set_status_to_permanent_failure(notify_api, notify_db_session, template=sample_email_template, reference='ref', - status='sending' + status='sending', + sent_at=datetime.utcnow() ) assert get_notification_by_id(notification.id).status == 'sending' @@ -612,12 +671,12 @@ 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_db, notify_db_session,notify_api, sample_notification, mocker): +def test_process_mmg_response_records_statsd(notify_db, notify_db_session, notify_api, mocker): with notify_api.test_client() as client: with freeze_time('2001-01-01T12:00:00'): mocker.patch('app.statsd_client.incr') - mocker.patch('app.statsd_client.timing') + mocker.patch('app.statsd_client.timing_with_dates') notification = create_sample_notification( notify_db, notify_db_session, status='sending', sent_at=datetime.utcnow() ) @@ -633,8 +692,8 @@ def test_process_mmg_response_records_statsd(notify_db, notify_db_session,notify 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 + app.statsd_client.timing_with_dates.assert_any_call( + "callback.mmg.elapsed-time", datetime.utcnow(), notification.sent_at ) @@ -644,7 +703,7 @@ def test_firetext_callback_should_record_statsd(notify_api, notify_db, notify_db with freeze_time('2001-01-01T12:00:00'): mocker.patch('app.statsd_client.incr') - mocker.patch('app.statsd_client.timing') + mocker.patch('app.statsd_client.timing_with_dates') notification = create_sample_notification( notify_db, notify_db_session, status='sending', sent_at=datetime.utcnow() ) @@ -656,8 +715,8 @@ def test_firetext_callback_should_record_statsd(notify_api, notify_db, notify_db ), 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.timing_with_dates.assert_any_call( + "callback.firetext.elapsed-time", datetime.utcnow(), notification.sent_at ) app.statsd_client.incr.assert_any_call("callback.firetext.delivered") From 34bd17ce66a2d5d0ba43373001c95acf40504056 Mon Sep 17 00:00:00 2001 From: Martyn Inglis Date: Tue, 13 Sep 2016 14:40:04 +0100 Subject: [PATCH 4/4] Record time in seconds --- app/clients/statsd/statsd_client.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/app/clients/statsd/statsd_client.py b/app/clients/statsd/statsd_client.py index cc404b8b5..dfc9db72e 100644 --- a/app/clients/statsd/statsd_client.py +++ b/app/clients/statsd/statsd_client.py @@ -27,5 +27,5 @@ class StatsdClient(StatsClient): def timing_with_dates(self, stat, start, end, rate=1): if self.active: - delta = (start - end).total_seconds() * 1000 + delta = (start - end).total_seconds() super(StatsClient, self).timing(stat, delta, rate)