Merge pull request #671 from alphagov/statsd-time-taken-to-be-delivered

Statsd time taken to be delivered

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()
+            super(StatsClient, self).timing(stat, delta, rate)

app/dao/notifications_dao.py

@@ -143,7 +143,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")
@@ -156,7 +156,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,
@@ -173,7 +173,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,

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,11 @@ def process_sms_client_response(status, reference, client_name):
                                                                                     notification_status_message))
 
     statsd_client.incr('callback.{}.{}'.format(client_name.lower(), notification_status))
+    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

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,12 @@ def process_ses_response():
                 )
 
             statsd_client.incr('callback.ses.{}'.format(notification_status))
+            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
@@ -231,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)
@@ -240,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'

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

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 (
@@ -139,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')])
 
@@ -157,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')])
 
@@ -182,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'
 
@@ -220,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',
@@ -261,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"})
@@ -275,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})
 
@@ -293,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})
 
@@ -311,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})
 
@@ -329,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})
 
@@ -347,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):
@@ -441,29 +498,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_with_dates')
+                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_with_dates.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(
@@ -479,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(
@@ -486,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(
@@ -493,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(
@@ -527,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(
@@ -555,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'
@@ -583,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'
@@ -600,35 +671,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, 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_with_dates')
+            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_with_dates.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_with_dates')
+                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_with_dates.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'):