From 1a4b303c4369d1adad46a47b96a3b436df4b9db1 Mon Sep 17 00:00:00 2001 From: Martyn Inglis Date: Tue, 13 Sep 2016 13:57:06 +0100 Subject: [PATCH] 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")