Logs time between sent_at and the provider callback into statsd

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

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'

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,

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'):