From 3f7559b286195b1dfb74cadabd1628d62f735992 Mon Sep 17 00:00:00 2001 From: Martyn Inglis Date: Fri, 13 May 2016 17:15:39 +0100 Subject: [PATCH 1/6] Added statsd integration into the API - new client for statsd, follows conventions used elsewhere for configuration - client wraps underlying library so we can use a config property to send/not send statsd Added statsd metrics for: - count of API successful calls SMS/Email - count of successful task execution for SMS/Email - count of errors from Client libraries - timing of API calls to third party clients - timing of how long messages live on the SQS queue --- app/__init__.py | 16 +-- app/celery/tasks.py | 20 +++- app/clients/email/aws_ses.py | 5 +- app/clients/sms/firetext.py | 5 +- app/clients/sms/loadtesting.py | 3 +- app/clients/sms/mmg.py | 5 +- app/clients/sms/twilio.py | 54 ---------- app/clients/statsd/__init__.py | 0 app/clients/statsd/statsd_client.py | 26 +++++ app/notifications/process_client_response.py | 3 + app/notifications/rest.py | 6 +- config.py | 10 +- config_live.py | 4 + environment_test.sh | 4 + requirements.txt | 2 +- tests/app/celery/test_tasks.py | 41 +++++++- tests/app/notifications/test_rest.py | 104 +++++++++++++++++++ 17 files changed, 234 insertions(+), 74 deletions(-) delete mode 100644 app/clients/sms/twilio.py create mode 100644 app/clients/statsd/__init__.py create mode 100644 app/clients/statsd/statsd_client.py diff --git a/app/__init__.py b/app/__init__.py index fbb31d3e9..be7bd43ed 100644 --- a/app/__init__.py +++ b/app/__init__.py @@ -1,5 +1,7 @@ import uuid import os + +import statsd from flask import request, url_for, g from flask import Flask, _request_ctx_stack from flask.ext.sqlalchemy import SQLAlchemy @@ -10,10 +12,10 @@ from notifications_utils import logging from app.celery.celery import NotifyCelery from app.clients import Clients from app.clients.sms.mmg import MMGClient -from app.clients.sms.twilio import TwilioClient from app.clients.sms.firetext import FiretextClient from app.clients.sms.loadtesting import LoadtestingClient from app.clients.email.aws_ses import AwsSesClient +from app.clients.statsd.statsd_client import StatsdClient from app.encryption import Encryption DATETIME_FORMAT = "%Y-%m-%dT%H:%M:%S.%f" @@ -22,12 +24,12 @@ DATE_FORMAT = "%Y-%m-%d" db = SQLAlchemy() ma = Marshmallow() notify_celery = NotifyCelery() -twilio_client = TwilioClient() firetext_client = FiretextClient() loadtest_client = LoadtestingClient() mmg_client = MMGClient() aws_ses_client = AwsSesClient() encryption = Encryption() +statsd_client = StatsdClient() clients = Clients() @@ -47,11 +49,11 @@ def create_app(app_name=None): ma.init_app(application) init_app(application) logging.init_app(application) - twilio_client.init_app(application) - firetext_client.init_app(application) - loadtest_client.init_app(application) - mmg_client.init_app(application.config) - aws_ses_client.init_app(application.config['AWS_REGION']) + statsd_client.init_app(application) + firetext_client.init_app(application, statsd_client=statsd_client) + loadtest_client.init_app(application, statsd_client=statsd_client) + mmg_client.init_app(application.config, statsd_client=statsd_client) + aws_ses_client.init_app(application.config['AWS_REGION'], statsd_client=statsd_client) notify_celery.init_app(application) encryption.init_app(application) clients.init_app(sms_clients=[firetext_client, mmg_client, loadtest_client], email_clients=[aws_ses_client]) diff --git a/app/celery/tasks.py b/app/celery/tasks.py index ffe614f77..767c7d4d9 100644 --- a/app/celery/tasks.py +++ b/app/celery/tasks.py @@ -3,7 +3,7 @@ from datetime import datetime from flask import current_app from sqlalchemy.exc import SQLAlchemyError -from app import clients +from app import clients, statsd_client from app.clients.email import EmailClientException from app.clients.sms import SmsClientException from app.dao.services_dao import dao_fetch_service_by_id @@ -190,6 +190,7 @@ def process_job(job_id): current_app.logger.info( "Job {} created at {} started at {} finished at {}".format(job_id, job.created_at, start, finished) ) + statsd_client.incr("notifications.tasks.process-job") @notify_celery.task(name="remove-job") @@ -235,7 +236,11 @@ def send_sms(service_id, notification_id, encrypted_notification, created_at): sent_by=provider.get_name(), content_char_count=template.replaced_content_count ) - + statsd_client.timing_with_dates( + "notifications.tasks.send-sms.queued-for", + sent_at, + datetime.strptime(created_at, DATETIME_FORMAT) + ) dao_create_notification(notification_db_object, TEMPLATE_TYPE_SMS, provider.get_name()) if restricted: @@ -259,6 +264,7 @@ def send_sms(service_id, notification_id, encrypted_notification, created_at): current_app.logger.info( "SMS {} created at {} sent at {}".format(notification_id, created_at, sent_at) ) + statsd_client.incr("notifications.tasks.send-sms") except SQLAlchemyError as e: current_app.logger.exception(e) @@ -293,6 +299,11 @@ def send_email(service_id, notification_id, from_address, encrypted_notification ) dao_create_notification(notification_db_object, TEMPLATE_TYPE_EMAIL, provider.get_name()) + statsd_client.timing_with_dates( + "notifications.tasks.send-email.queued-for", + sent_at, + datetime.strptime(created_at, DATETIME_FORMAT) + ) if restricted: return @@ -309,15 +320,18 @@ def send_email(service_id, notification_id, from_address, encrypted_notification body=template.replaced_govuk_escaped, html_body=template.as_HTML_email, ) + update_notification_reference_by_id(notification_id, reference) + except EmailClientException as e: current_app.logger.exception(e) notification_db_object.status = 'failed' + dao_update_notification(notification_db_object) - dao_update_notification(notification_db_object) current_app.logger.info( "Email {} created at {} sent at {}".format(notification_id, created_at, sent_at) ) + statsd_client.incr("notifications.tasks.send-email") except SQLAlchemyError as e: current_app.logger.exception(e) diff --git a/app/clients/email/aws_ses.py b/app/clients/email/aws_ses.py index ce139ceff..afb34af57 100644 --- a/app/clients/email/aws_ses.py +++ b/app/clients/email/aws_ses.py @@ -39,10 +39,11 @@ class AwsSesClient(EmailClient): Amazon SES email client. ''' - def init_app(self, region, *args, **kwargs): + def init_app(self, region, statsd_client, *args, **kwargs): self._client = boto3.client('ses', region_name=region) super(AwsSesClient, self).__init__(*args, **kwargs) self.name = 'ses' + self.statsd_client = statsd_client def get_name(self): return self.name @@ -88,7 +89,9 @@ class AwsSesClient(EmailClient): ReplyToAddresses=reply_to_addresses) elapsed_time = monotonic() - start_time current_app.logger.info("AWS SES request finished in {}".format(elapsed_time)) + self.statsd_client.timing("notifications.clients.ses.request-time", elapsed_time) return response['MessageId'] except Exception as e: # TODO logging exceptions + self.statsd_client.incr("notifications.clients.ses.error") raise AwsSesClientException(str(e)) diff --git a/app/clients/sms/firetext.py b/app/clients/sms/firetext.py index 7c49848b4..5269d9444 100644 --- a/app/clients/sms/firetext.py +++ b/app/clients/sms/firetext.py @@ -50,11 +50,12 @@ class FiretextClient(SmsClient): FireText sms client. ''' - def init_app(self, config, *args, **kwargs): + def init_app(self, config, statsd_client, *args, **kwargs): super(SmsClient, self).__init__(*args, **kwargs) self.api_key = config.config.get('FIRETEXT_API_KEY') self.from_number = config.config.get('FIRETEXT_NUMBER') self.name = 'firetext' + self.statsd_client = statsd_client def get_name(self): return self.name @@ -90,8 +91,10 @@ class FiretextClient(SmsClient): api_error.message ) ) + self.statsd_client.incr("notifications.clients.firetext.error") raise api_error finally: elapsed_time = monotonic() - start_time current_app.logger.info("Firetext request finished in {}".format(elapsed_time)) + self.statsd_client.timing("notifications.clients.firetext.request-time", elapsed_time) return response diff --git a/app/clients/sms/loadtesting.py b/app/clients/sms/loadtesting.py index 755578a86..a3e500ba8 100644 --- a/app/clients/sms/loadtesting.py +++ b/app/clients/sms/loadtesting.py @@ -11,8 +11,9 @@ class LoadtestingClient(FiretextClient): Loadtest sms client. ''' - def init_app(self, config, *args, **kwargs): + def init_app(self, config, statsd_client, *args, **kwargs): super(FiretextClient, self).__init__(*args, **kwargs) self.api_key = config.config.get('LOADTESTING_API_KEY') self.from_number = config.config.get('LOADTESTING_NUMBER') self.name = 'loadtesting' + self.statsd_client = statsd_client diff --git a/app/clients/sms/mmg.py b/app/clients/sms/mmg.py index 271b280b4..d0b409db5 100644 --- a/app/clients/sms/mmg.py +++ b/app/clients/sms/mmg.py @@ -39,11 +39,12 @@ class MMGClient(SmsClient): MMG sms client ''' - def init_app(self, config, *args, **kwargs): + def init_app(self, config, statsd_client, *args, **kwargs): super(SmsClient, self).__init__(*args, **kwargs) self.api_key = config.get('MMG_API_KEY') self.from_number = config.get('MMG_FROM_NUMBER') self.name = 'mmg' + self.statsd_client = statsd_client def get_name(self): return self.name @@ -78,8 +79,10 @@ class MMGClient(SmsClient): api_error.message ) ) + self.statsd_client.incr("notifications.clients.mmg.error") raise api_error finally: elapsed_time = monotonic() - start_time + self.statsd_client.timing("notifications.clients.mmg.request-time", elapsed_time) current_app.logger.info("MMG request finished in {}".format(elapsed_time)) return response diff --git a/app/clients/sms/twilio.py b/app/clients/sms/twilio.py deleted file mode 100644 index d030cbdf5..000000000 --- a/app/clients/sms/twilio.py +++ /dev/null @@ -1,54 +0,0 @@ -from monotonic import monotonic -from app.clients.sms import ( - SmsClient, SmsClientException) -from twilio.rest import TwilioRestClient -from twilio import TwilioRestException -from flask import current_app - - -class TwilioClientException(SmsClientException): - pass - - -class TwilioClient(SmsClient): - ''' - Twilio sms client. - ''' - def init_app(self, config, *args, **kwargs): - super(TwilioClient, self).__init__(*args, **kwargs) - self.client = TwilioRestClient( - config.config.get('TWILIO_ACCOUNT_SID'), - config.config.get('TWILIO_AUTH_TOKEN')) - self.from_number = config.config.get('TWILIO_NUMBER') - self.name = 'twilio' - - def get_name(self): - return self.name - - def send_sms(self, to, content): - start_time = monotonic() - try: - response = self.client.messages.create( - body=content, - to=to, - from_=self.from_number - ) - return response.sid - except TwilioRestException as e: - current_app.logger.exception(e) - raise TwilioClientException(e) - finally: - elapsed_time = monotonic() - start_time - current_app.logger.info("Twilio request finished in {}".format(elapsed_time)) - - def status(self, message_id): - try: - response = self.client.messages.get(message_id) - if response.status in ('delivered', 'failed'): - return response.status - elif response.status == 'undelivered': - return 'sending' - return None - except TwilioRestException as e: - current_app.logger.exception(e) - raise TwilioClientException(e) diff --git a/app/clients/statsd/__init__.py b/app/clients/statsd/__init__.py new file mode 100644 index 000000000..e69de29bb diff --git a/app/clients/statsd/statsd_client.py b/app/clients/statsd/statsd_client.py new file mode 100644 index 000000000..8809c4952 --- /dev/null +++ b/app/clients/statsd/statsd_client.py @@ -0,0 +1,26 @@ +from statsd import StatsClient + + +class StatsdClient(StatsClient): + def init_app(self, app, *args, **kwargs): + StatsClient.__init__( + self, + app.config.get('STATSD_HOST'), + app.config.get('STATSD_PORT'), + prefix=app.config.get('STATSD_PREFIX') + ) + self.active = app.config.get('STATSD_ENABLED') + + def incr(self, stat, count=1, rate=1): + if self.active: + super(StatsClient, self).incr(stat, count, rate) + + def timing(self, stat, delta, rate=1): + if self.active: + super(StatsClient, self).timing(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) \ No newline at end of file diff --git a/app/notifications/process_client_response.py b/app/notifications/process_client_response.py index bbed09d1f..01f1b4c62 100644 --- a/app/notifications/process_client_response.py +++ b/app/notifications/process_client_response.py @@ -1,5 +1,7 @@ import uuid from flask import current_app + +from app import statsd_client from app.dao import notifications_dao from app.clients.sms.firetext import get_firetext_responses from app.clients.sms.mmg import get_mmg_responses @@ -67,5 +69,6 @@ def process_sms_client_response(status, reference, client_name): reference, notification_status_message)) + statsd_client.incr('notifications.callback.{}.{}'.format(client_name.lower(), notification_statistics_status)) 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 4749203c9..645d2db60 100644 --- a/app/notifications/rest.py +++ b/app/notifications/rest.py @@ -1,5 +1,5 @@ from datetime import datetime - +import statsd import itertools from flask import ( Blueprint, @@ -12,7 +12,7 @@ from flask import ( from notifications_utils.recipients import allowed_to_send_to, first_column_heading from notifications_utils.template import Template from app.clients.email.aws_ses import get_aws_responses -from app import api_user, encryption, create_uuid, DATETIME_FORMAT, DATE_FORMAT +from app import api_user, encryption, create_uuid, DATETIME_FORMAT, DATE_FORMAT, statsd_client from app.authentication.auth import require_admin from app.dao import ( templates_dao, @@ -103,6 +103,7 @@ def process_ses_response(): ) ) + statsd_client.incr('notifications.callback.ses.{}'.format(notification_statistics_status)) return jsonify( result="success", message="SES callback succeeded" ), 200 @@ -374,4 +375,5 @@ def send_notification(notification_type): datetime.utcnow().strftime(DATETIME_FORMAT) ), queue='email') + statsd_client.incr('notifications.api.{}'.format(notification_type)) return jsonify(data={"notification": {"id": notification_id}}), 201 diff --git a/config.py b/config.py index 6ebed4c64..3e1062538 100644 --- a/config.py +++ b/config.py @@ -87,12 +87,20 @@ class Config(object): CSV_UPLOAD_BUCKET_NAME = 'local-notifications-csv-upload' NOTIFICATIONS_ALERT = 5 # five mins + STATSD_ENABLED = False + STATSD_HOST = "localhost" + STATSD_PORT = None + STATSD_PREFIX = None + class Development(Config): DEBUG = True MMG_API_KEY = os.environ['MMG_API_KEY'] CSV_UPLOAD_BUCKET_NAME = 'development-notifications-csv-upload' - + STATSD_ENABLED = True + STATSD_HOST = os.getenv('STATSD_HOST') + STATSD_PORT = os.getenv('STATSD_PORT') + STATSD_PREFIX = os.getenv('STATSD_PREFIX') class Preview(Config): MMG_API_KEY = os.environ['MMG_API_KEY'] diff --git a/config_live.py b/config_live.py index 470643b89..35e53470b 100644 --- a/config_live.py +++ b/config_live.py @@ -18,6 +18,10 @@ class Live(Config): TWILIO_AUTH_TOKEN = os.getenv('LIVE_TWILIO_AUTH_TOKEN') MMG_API_KEY = os.environ['LIVE_MMG_API_KEY'] CSV_UPLOAD_BUCKET_NAME = 'live-notifications-csv-upload' + STATSD_ENABLED = True + STATSD_HOST = os.getenv('LIVE_STATSD_HOST') + STATSD_PORT = os.getenv('LIVE_STATSD_PORT') + STATSD_PREFIX = os.getenv('LIVE_STATSD_PREFIX') BROKER_TRANSPORT_OPTIONS = { 'region': 'eu-west-1', diff --git a/environment_test.sh b/environment_test.sh index f07f9bccf..4969cd90d 100644 --- a/environment_test.sh +++ b/environment_test.sh @@ -22,3 +22,7 @@ export MMG_API_KEY='mmg-secret-key' export MMG_FROM_NUMBER='test' export LOADTESTING_API_KEY="loadtesting" export LOADTESTING_NUMBER="loadtesting" +export STATSD_ENABLED=True +export STATSD_HOST="somehost" +export STATSD_PORT=1000 +export STATSD_PREFIX="stats-prefix" \ No newline at end of file diff --git a/requirements.txt b/requirements.txt index 50ded66b5..723d168df 100644 --- a/requirements.txt +++ b/requirements.txt @@ -17,7 +17,7 @@ boto==2.39.0 celery==3.1.20 twilio==4.6.0 monotonic==0.3 - +statsd==3.2.1 git+https://github.com/alphagov/notifications-python-client.git@1.0.0#egg=notifications-python-client==1.0.0 diff --git a/tests/app/celery/test_tasks.py b/tests/app/celery/test_tasks.py index 31bbd4ad9..bb6f0590c 100644 --- a/tests/app/celery/test_tasks.py +++ b/tests/app/celery/test_tasks.py @@ -16,7 +16,7 @@ from app.celery.tasks import ( delete_successful_notifications, provider_to_use ) -from app import (aws_ses_client, encryption, DATETIME_FORMAT, mmg_client) +from app import (aws_ses_client, encryption, DATETIME_FORMAT, mmg_client, statsd_client) from app.clients.email.aws_ses import AwsSesClientException from app.clients.sms.mmg import MMGClientException from app.dao import notifications_dao, jobs_dao, provider_details_dao @@ -103,6 +103,7 @@ def test_should_call_delete_invotations_on_delete_invitations_task(notify_api, m @freeze_time("2016-01-01 11:09:00.061258") def test_should_process_sms_job(sample_job, mocker, mock_celery_remove_job): + mocker.patch('app.statsd_client.incr') mocker.patch('app.celery.tasks.s3.get_job_from_s3', return_value=load_example_csv('sms')) mocker.patch('app.celery.tasks.send_sms.apply_async') mocker.patch('app.encryption.encrypt', return_value="something_encrypted") @@ -124,6 +125,7 @@ def test_should_process_sms_job(sample_job, mocker, mock_celery_remove_job): ) job = jobs_dao.dao_get_job_by_id(sample_job.id) assert job.status == 'finished' + statsd_client.incr.assert_called_once_with("notifications.tasks.process-job") @freeze_time("2016-01-01 11:09:00.061258") @@ -329,21 +331,37 @@ def test_should_send_template_to_correct_sms_provider_and_persist(sample_templat mocker.patch('app.encryption.decrypt', return_value=notification) mocker.patch('app.mmg_client.send_sms') mocker.patch('app.mmg_client.get_name', return_value="mmg") + mocker.patch('app.statsd_client.incr') + mocker.patch('app.statsd_client.timing_with_dates') notification_id = uuid.uuid4() + + freezer = freeze_time("2016-01-01 11:09:00.00000") + freezer.start() now = datetime.utcnow() + freezer.stop() + + freezer = freeze_time("2016-01-01 11:10:00.00000") + freezer.start() + send_sms( sample_template_with_placeholders.service_id, notification_id, "encrypted-in-reality", now.strftime(DATETIME_FORMAT) ) + freezer.stop() + + statsd_client.timing_with_dates.assert_called_once_with( + "notifications.tasks.send-sms.queued-for", datetime(2016, 1, 1, 11, 10, 0, 00000), datetime(2016, 1, 1, 11, 9, 0, 00000) + ) mmg_client.send_sms.assert_called_once_with( to=format_phone_number(validate_phone_number("+447234123123")), content="Sample service: Hello Jo", reference=str(notification_id) ) + statsd_client.incr.assert_called_once_with("notifications.tasks.send-sms") persisted_notification = notifications_dao.get_notification( sample_template_with_placeholders.service_id, notification_id ) @@ -539,11 +557,21 @@ def test_should_use_email_template_and_persist(sample_email_template_with_placeh "personalisation": {"name": "Jo"} } mocker.patch('app.encryption.decrypt', return_value=notification) - mocker.patch('app.aws_ses_client.send_email') + mocker.patch('app.statsd_client.incr') + mocker.patch('app.statsd_client.timing_with_dates') mocker.patch('app.aws_ses_client.get_name', return_value='ses') + mocker.patch('app.aws_ses_client.send_email', return_value='ses') notification_id = uuid.uuid4() + + freezer = freeze_time("2016-01-01 11:09:00.00000") + freezer.start() now = datetime.utcnow() + freezer.stop() + + freezer = freeze_time("2016-01-01 11:10:00.00000") + freezer.start() + send_email( sample_email_template_with_placeholders.service_id, notification_id, @@ -551,6 +579,8 @@ def test_should_use_email_template_and_persist(sample_email_template_with_placeh "encrypted-in-reality", now.strftime(DATETIME_FORMAT) ) + freezer.stop() + aws_ses_client.send_email.assert_called_once_with( "email_from", "my_email@my_email.com", @@ -558,9 +588,16 @@ def test_should_use_email_template_and_persist(sample_email_template_with_placeh body="Hello Jo", html_body=AnyStringWith("Hello Jo") ) + + statsd_client.incr.assert_called_once_with("notifications.tasks.send-email") + statsd_client.timing_with_dates.assert_called_once_with( + "notifications.tasks.send-email.queued-for", datetime(2016, 1, 1, 11, 10, 0, 00000), datetime(2016, 1, 1, 11, 9, 0, 00000) + ) + persisted_notification = notifications_dao.get_notification( sample_email_template_with_placeholders.service_id, notification_id ) + assert persisted_notification.id == notification_id assert persisted_notification.to == 'my_email@my_email.com' assert persisted_notification.template_id == sample_email_template_with_placeholders.id diff --git a/tests/app/notifications/test_rest.py b/tests/app/notifications/test_rest.py index 0f8567961..b2aef21f5 100644 --- a/tests/app/notifications/test_rest.py +++ b/tests/app/notifications/test_rest.py @@ -1510,6 +1510,110 @@ def test_should_handle_validation_code_callbacks(notify_api, notify_db, notify_d assert json_resp['message'] == 'SES callback succeeded' +def test_should_record_email_request_in_statsd(notify_api, notify_db, notify_db_session, sample_email_template, mocker): + with notify_api.test_request_context(): + with notify_api.test_client() as client: + mocker.patch('app.statsd_client.incr') + mocker.patch('app.celery.tasks.send_email.apply_async') + mocker.patch('app.encryption.encrypt', return_value="something_encrypted") + + data = { + 'to': 'ok@ok.com', + 'template': str(sample_email_template.id) + } + + auth_header = create_authorization_header(service_id=sample_email_template.service_id) + + response = client.post( + path='/notifications/email', + data=json.dumps(data), + headers=[('Content-Type', 'application/json'), auth_header]) + assert response.status_code == 201 + app.statsd_client.incr.assert_called_once_with("notification.api.email") + + +def test_should_record_sms_request_in_statsd(notify_api, notify_db, notify_db_session, sample_template, mocker): + with notify_api.test_request_context(): + with notify_api.test_client() as client: + mocker.patch('app.statsd_client.incr') + mocker.patch('app.celery.tasks.send_sms.apply_async') + mocker.patch('app.encryption.encrypt', return_value="something_encrypted") + + data = { + 'to': '07123123123', + 'template': str(sample_template.id) + } + + auth_header = create_authorization_header(service_id=sample_template.service_id) + + response = client.post( + path='/notifications/sms', + data=json.dumps(data), + headers=[('Content-Type', 'application/json'), auth_header]) + assert response.status_code == 201 + app.statsd_client.incr.assert_called_once_with("notification.api.sms") + + +def test_ses_callback_should_update_record_statsd( + notify_api, + notify_db, + notify_db_session, + sample_email_template, + 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, + template=sample_email_template, + reference='ref' + ) + + assert get_notification_by_id(notification.id).status == 'sending' + + client.post( + path='/notifications/email/ses', + data=ses_notification_callback(), + headers=[('Content-Type', 'text/plain; charset=UTF-8')] + ) + app.statsd_client.incr.assert_called_once_with("notifications.callback.ses.delivered") + + +def test_process_mmg_response_records_statsd(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"}) + + client.post(path='notifications/sms/mmg', + data=data, + headers=[('Content-Type', 'application/json')]) + app.statsd_client.incr.assert_called_once_with("notifications.callback.mmg.delivered") + + + +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='delivered') + + client.post( + path='/notifications/sms/firetext', + data='mobile=441234123123&status=2&time=2016-03-10 14:17:00&reference={}'.format( + notification.id + ), + headers=[('Content-Type', 'application/x-www-form-urlencoded')]) + + app.statsd_client.incr.assert_called_once_with("notifications.callback.firetext.delivered") + + + def ses_validation_code_callback(): return b'{\n "Type" : "Notification",\n "MessageId" : "ref",\n "TopicArn" : "arn:aws:sns:eu-west-1:123456789012:testing",\n "Message" : "{\\"notificationType\\":\\"Delivery\\",\\"mail\\":{\\"timestamp\\":\\"2016-03-14T12:35:25.909Z\\",\\"source\\":\\"valid-code@test.com\\",\\"sourceArn\\":\\"arn:aws:ses:eu-west-1:123456789012:identity/testing-notify\\",\\"sendingAccountId\\":\\"123456789012\\",\\"messageId\\":\\"ref\\",\\"destination\\":[\\"testing@digital.cabinet-office.gov.uk\\"]},\\"delivery\\":{\\"timestamp\\":\\"2016-03-14T12:35:26.567Z\\",\\"processingTimeMillis\\":658,\\"recipients\\":[\\"testing@digital.cabinet-office.gov.u\\"],\\"smtpResponse\\":\\"250 2.0.0 OK 1457958926 uo5si26480932wjc.221 - gsmtp\\",\\"reportingMTA\\":\\"a6-238.smtp-out.eu-west-1.amazonses.com\\"}}",\n "Timestamp" : "2016-03-14T12:35:26.665Z",\n "SignatureVersion" : "1",\n "Signature" : "X8d7eTAOZ6wlnrdVVPYanrAlsX0SMPfOzhoTEBnQqYkrNWTqQY91C0f3bxtPdUhUtOowyPAOkTQ4KnZuzphfhVb2p1MyVYMxNKcBFB05/qaCX99+92fjw4x9LeUOwyGwMv5F0Vkfi5qZCcEw69uVrhYLVSTFTrzi/yCtru+yFULMQ6UhbY09GwiP6hjxZMVr8aROQy5lLHglqQzOuSZ4KeD85JjifHdKzlx8jjQ+uj+FLzHXPMAPmPU1JK9kpoHZ1oPshAFgPDpphJe+HwcJ8ezmk+3AEUr3wWli3xF+49y8Z2anASSVp6YI2YP95UT8Rlh3qT3T+V9V8rbSVislxA==",\n "SigningCertURL" : "https://sns.eu-west-1.amazonaws.com/SimpleNotificationService-bb750dd426d95ee9390147a5624348ee.pem",\n "UnsubscribeURL" : "https://sns.eu-west-1.amazonaws.com/?Action=Unsubscribe&SubscriptionArn=arn:aws:sns:eu-west-1:302763885840:preview-emails:d6aad3ef-83d6-4cf3-a470-54e2e75916da"\n}' # noqa From 829d86273963d7cc15288052eea73929d386d88c Mon Sep 17 00:00:00 2001 From: Martyn Inglis Date: Fri, 13 May 2016 17:20:29 +0100 Subject: [PATCH 2/6] Fixed pep8 issues and hostname in the test environment. --- app/clients/statsd/statsd_client.py | 3 +-- config.py | 1 + environment_test.sh | 4 ++-- tests/app/notifications/test_rest.py | 18 ++---------------- 4 files changed, 6 insertions(+), 20 deletions(-) diff --git a/app/clients/statsd/statsd_client.py b/app/clients/statsd/statsd_client.py index 8809c4952..986aa2628 100644 --- a/app/clients/statsd/statsd_client.py +++ b/app/clients/statsd/statsd_client.py @@ -19,8 +19,7 @@ class StatsdClient(StatsClient): if self.active: super(StatsClient, self).timing(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) \ No newline at end of file + super(StatsClient, self).timing(stat, delta, rate) diff --git a/config.py b/config.py index 3e1062538..fe3b983dd 100644 --- a/config.py +++ b/config.py @@ -102,6 +102,7 @@ class Development(Config): STATSD_PORT = os.getenv('STATSD_PORT') STATSD_PREFIX = os.getenv('STATSD_PREFIX') + class Preview(Config): MMG_API_KEY = os.environ['MMG_API_KEY'] CSV_UPLOAD_BUCKET_NAME = 'preview-notifications-csv-upload' diff --git a/environment_test.sh b/environment_test.sh index 4969cd90d..137ce3ff5 100644 --- a/environment_test.sh +++ b/environment_test.sh @@ -23,6 +23,6 @@ export MMG_FROM_NUMBER='test' export LOADTESTING_API_KEY="loadtesting" export LOADTESTING_NUMBER="loadtesting" export STATSD_ENABLED=True -export STATSD_HOST="somehost" +export STATSD_HOST="localhost" export STATSD_PORT=1000 -export STATSD_PREFIX="stats-prefix" \ No newline at end of file +export STATSD_PREFIX="stats-prefix" diff --git a/tests/app/notifications/test_rest.py b/tests/app/notifications/test_rest.py index b2aef21f5..341a1ddb1 100644 --- a/tests/app/notifications/test_rest.py +++ b/tests/app/notifications/test_rest.py @@ -286,7 +286,6 @@ def test_get_all_notifications_returns_empty_list(notify_api, sample_api_key): def test_filter_by_template_type(notify_api, notify_db, notify_db_session, sample_template, sample_email_template): with notify_api.test_request_context(): with notify_api.test_client() as client: - notification_1 = create_sample_notification( notify_db, notify_db_session, @@ -317,7 +316,6 @@ def test_filter_by_multiple_template_types(notify_api, sample_email_template): with notify_api.test_request_context(): with notify_api.test_client() as client: - notification_1 = create_sample_notification( notify_db, notify_db_session, @@ -345,7 +343,6 @@ def test_filter_by_multiple_template_types(notify_api, def test_filter_by_status(notify_api, notify_db, notify_db_session, sample_email_template): with notify_api.test_request_context(): with notify_api.test_client() as client: - notification_1 = create_sample_notification( notify_db, notify_db_session, @@ -377,7 +374,6 @@ def test_filter_by_multiple_statuss(notify_api, sample_email_template): with notify_api.test_request_context(): with notify_api.test_client() as client: - notification_1 = create_sample_notification( notify_db, notify_db_session, @@ -411,7 +407,6 @@ def test_filter_by_status_and_template_type(notify_api, sample_email_template): with notify_api.test_request_context(): with notify_api.test_client() as client: - notification_1 = create_sample_notification( notify_db, notify_db_session, @@ -946,7 +941,6 @@ def test_no_limit_for_live_service(notify_api, sample_notification): with notify_api.test_request_context(): with notify_api.test_client() as client: - sample_service.message_limit = 1 notify_db.session.add(sample_service) notify_db.session.commit() @@ -1347,7 +1341,6 @@ def test_ses_callback_should_fail_if_invalid_json(notify_api): def test_ses_callback_should_fail_if_invalid_notification_type(notify_api): with notify_api.test_request_context(): with notify_api.test_client() as client: - response = client.post( path='/notifications/email/ses', data=ses_invalid_notification_type_callback(), @@ -1362,7 +1355,6 @@ def test_ses_callback_should_fail_if_invalid_notification_type(notify_api): def test_ses_callback_should_fail_if_missing_message_id(notify_api): with notify_api.test_request_context(): with notify_api.test_client() as client: - response = client.post( path='/notifications/email/ses', data=ses_missing_notification_id_callback(), @@ -1377,7 +1369,6 @@ def test_ses_callback_should_fail_if_missing_message_id(notify_api): def test_ses_callback_should_fail_if_notification_cannot_be_found(notify_db, notify_db_session, notify_api): with notify_api.test_request_context(): with notify_api.test_client() as client: - response = client.post( path='/notifications/email/ses', data=ses_invalid_notification_id_callback(), @@ -1427,7 +1418,6 @@ def test_ses_callback_should_update_multiple_notification_status_sent( sample_email_template): with notify_api.test_request_context(): with notify_api.test_client() as client: - notification1 = create_sample_notification( notify_db, notify_db_session, @@ -1478,7 +1468,6 @@ def test_ses_callback_should_update_multiple_notification_status_sent( def test_should_handle_invite_email_callbacks(notify_api, notify_db, notify_db_session): with notify_api.test_request_context(): with notify_api.test_client() as client: - notify_api.config['INVITATION_EMAIL_FROM'] = 'test-invite' notify_api.config['NOTIFY_EMAIL_DOMAIN'] = 'test-domain.com' @@ -1496,7 +1485,6 @@ def test_should_handle_invite_email_callbacks(notify_api, notify_db, notify_db_s def test_should_handle_validation_code_callbacks(notify_api, notify_db, notify_db_session): with notify_api.test_request_context(): with notify_api.test_client() as client: - notify_api.config['VERIFY_CODE_FROM_EMAIL_ADDRESS'] = 'valid-code@test.com' response = client.post( @@ -1591,12 +1579,11 @@ def test_process_mmg_response_records_statsd(notify_api, sample_notification, mo "deliverytime": "2016-04-05 16:01:07"}) client.post(path='notifications/sms/mmg', - data=data, - headers=[('Content-Type', 'application/json')]) + data=data, + headers=[('Content-Type', 'application/json')]) app.statsd_client.incr.assert_called_once_with("notifications.callback.mmg.delivered") - 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: @@ -1613,7 +1600,6 @@ def test_firetext_callback_should_record_statsd(notify_api, notify_db, notify_db app.statsd_client.incr.assert_called_once_with("notifications.callback.firetext.delivered") - def ses_validation_code_callback(): return b'{\n "Type" : "Notification",\n "MessageId" : "ref",\n "TopicArn" : "arn:aws:sns:eu-west-1:123456789012:testing",\n "Message" : "{\\"notificationType\\":\\"Delivery\\",\\"mail\\":{\\"timestamp\\":\\"2016-03-14T12:35:25.909Z\\",\\"source\\":\\"valid-code@test.com\\",\\"sourceArn\\":\\"arn:aws:ses:eu-west-1:123456789012:identity/testing-notify\\",\\"sendingAccountId\\":\\"123456789012\\",\\"messageId\\":\\"ref\\",\\"destination\\":[\\"testing@digital.cabinet-office.gov.uk\\"]},\\"delivery\\":{\\"timestamp\\":\\"2016-03-14T12:35:26.567Z\\",\\"processingTimeMillis\\":658,\\"recipients\\":[\\"testing@digital.cabinet-office.gov.u\\"],\\"smtpResponse\\":\\"250 2.0.0 OK 1457958926 uo5si26480932wjc.221 - gsmtp\\",\\"reportingMTA\\":\\"a6-238.smtp-out.eu-west-1.amazonses.com\\"}}",\n "Timestamp" : "2016-03-14T12:35:26.665Z",\n "SignatureVersion" : "1",\n "Signature" : "X8d7eTAOZ6wlnrdVVPYanrAlsX0SMPfOzhoTEBnQqYkrNWTqQY91C0f3bxtPdUhUtOowyPAOkTQ4KnZuzphfhVb2p1MyVYMxNKcBFB05/qaCX99+92fjw4x9LeUOwyGwMv5F0Vkfi5qZCcEw69uVrhYLVSTFTrzi/yCtru+yFULMQ6UhbY09GwiP6hjxZMVr8aROQy5lLHglqQzOuSZ4KeD85JjifHdKzlx8jjQ+uj+FLzHXPMAPmPU1JK9kpoHZ1oPshAFgPDpphJe+HwcJ8ezmk+3AEUr3wWli3xF+49y8Z2anASSVp6YI2YP95UT8Rlh3qT3T+V9V8rbSVislxA==",\n "SigningCertURL" : "https://sns.eu-west-1.amazonaws.com/SimpleNotificationService-bb750dd426d95ee9390147a5624348ee.pem",\n "UnsubscribeURL" : "https://sns.eu-west-1.amazonaws.com/?Action=Unsubscribe&SubscriptionArn=arn:aws:sns:eu-west-1:302763885840:preview-emails:d6aad3ef-83d6-4cf3-a470-54e2e75916da"\n}' # noqa From a520dcef473d5ac9cef933af1ce81bf2e221c219 Mon Sep 17 00:00:00 2001 From: Martyn Inglis Date: Fri, 13 May 2016 17:22:03 +0100 Subject: [PATCH 3/6] Fixed some more pep8 --- tests/app/celery/test_tasks.py | 8 ++++++-- 1 file changed, 6 insertions(+), 2 deletions(-) diff --git a/tests/app/celery/test_tasks.py b/tests/app/celery/test_tasks.py index bb6f0590c..f2818861d 100644 --- a/tests/app/celery/test_tasks.py +++ b/tests/app/celery/test_tasks.py @@ -353,7 +353,9 @@ def test_should_send_template_to_correct_sms_provider_and_persist(sample_templat freezer.stop() statsd_client.timing_with_dates.assert_called_once_with( - "notifications.tasks.send-sms.queued-for", datetime(2016, 1, 1, 11, 10, 0, 00000), datetime(2016, 1, 1, 11, 9, 0, 00000) + "notifications.tasks.send-sms.queued-for", + datetime(2016, 1, 1, 11, 10, 0, 00000), + datetime(2016, 1, 1, 11, 9, 0, 00000) ) mmg_client.send_sms.assert_called_once_with( @@ -591,7 +593,9 @@ def test_should_use_email_template_and_persist(sample_email_template_with_placeh statsd_client.incr.assert_called_once_with("notifications.tasks.send-email") statsd_client.timing_with_dates.assert_called_once_with( - "notifications.tasks.send-email.queued-for", datetime(2016, 1, 1, 11, 10, 0, 00000), datetime(2016, 1, 1, 11, 9, 0, 00000) + "notifications.tasks.send-email.queued-for", + datetime(2016, 1, 1, 11, 10, 0, 00000), + datetime(2016, 1, 1, 11, 9, 0, 00000) ) persisted_notification = notifications_dao.get_notification( From a60e11a1b6dea61e3f78b404e7ae96dd2fcfa3e9 Mon Sep 17 00:00:00 2001 From: Martyn Inglis Date: Fri, 13 May 2016 17:25:34 +0100 Subject: [PATCH 4/6] Fixed test bug due to pluralisation typo --- tests/app/notifications/test_rest.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/tests/app/notifications/test_rest.py b/tests/app/notifications/test_rest.py index 341a1ddb1..9c5e6bc17 100644 --- a/tests/app/notifications/test_rest.py +++ b/tests/app/notifications/test_rest.py @@ -1517,7 +1517,7 @@ def test_should_record_email_request_in_statsd(notify_api, notify_db, notify_db_ data=json.dumps(data), headers=[('Content-Type', 'application/json'), auth_header]) assert response.status_code == 201 - app.statsd_client.incr.assert_called_once_with("notification.api.email") + app.statsd_client.incr.assert_called_once_with("notifications.api.email") def test_should_record_sms_request_in_statsd(notify_api, notify_db, notify_db_session, sample_template, mocker): @@ -1539,7 +1539,7 @@ def test_should_record_sms_request_in_statsd(notify_api, notify_db, notify_db_se data=json.dumps(data), headers=[('Content-Type', 'application/json'), auth_header]) assert response.status_code == 201 - app.statsd_client.incr.assert_called_once_with("notification.api.sms") + app.statsd_client.incr.assert_called_once_with("notifications.api.sms") def test_ses_callback_should_update_record_statsd( From 785def9117c95f0f472f0d6cc69551bc222da2c2 Mon Sep 17 00:00:00 2001 From: Martyn Inglis Date: Mon, 16 May 2016 11:55:00 +0100 Subject: [PATCH 5/6] Timed the tasks - how long to process a task / a sms-send / a email-send --- app/celery/tasks.py | 7 +++++++ tests/app/celery/test_tasks.py | 8 +++++++- 2 files changed, 14 insertions(+), 1 deletion(-) diff --git a/app/celery/tasks.py b/app/celery/tasks.py index 767c7d4d9..887ca6468 100644 --- a/app/celery/tasks.py +++ b/app/celery/tasks.py @@ -2,6 +2,7 @@ import itertools from datetime import datetime from flask import current_app +from monotonic import monotonic from sqlalchemy.exc import SQLAlchemyError from app import clients, statsd_client from app.clients.email import EmailClientException @@ -112,6 +113,7 @@ def delete_invitations(): @notify_celery.task(name="process-job") def process_job(job_id): + task_start = monotonic() start = datetime.utcnow() job = dao_get_job_by_id(job_id) @@ -191,6 +193,7 @@ def process_job(job_id): "Job {} created at {} started at {} finished at {}".format(job_id, job.created_at, start, finished) ) statsd_client.incr("notifications.tasks.process-job") + statsd_client.timing("notifications.tasks.process-job.task-time", monotonic() - task_start) @notify_celery.task(name="remove-job") @@ -202,6 +205,7 @@ def remove_job(job_id): @notify_celery.task(name="send-sms") def send_sms(service_id, notification_id, encrypted_notification, created_at): + task_start = monotonic() notification = encryption.decrypt(encrypted_notification) service = dao_fetch_service_by_id(service_id) @@ -265,12 +269,14 @@ def send_sms(service_id, notification_id, encrypted_notification, created_at): "SMS {} created at {} sent at {}".format(notification_id, created_at, sent_at) ) statsd_client.incr("notifications.tasks.send-sms") + statsd_client.timing("notifications.tasks.send-sms.task-time", monotonic() - task_start) except SQLAlchemyError as e: current_app.logger.exception(e) @notify_celery.task(name="send-email") def send_email(service_id, notification_id, from_address, encrypted_notification, created_at): + task_start = monotonic() notification = encryption.decrypt(encrypted_notification) service = dao_fetch_service_by_id(service_id) @@ -332,6 +338,7 @@ def send_email(service_id, notification_id, from_address, encrypted_notification "Email {} created at {} sent at {}".format(notification_id, created_at, sent_at) ) statsd_client.incr("notifications.tasks.send-email") + statsd_client.timing("notifications.tasks.send-email.task-time", monotonic() - task_start) except SQLAlchemyError as e: current_app.logger.exception(e) diff --git a/tests/app/celery/test_tasks.py b/tests/app/celery/test_tasks.py index f2818861d..d4b982ee2 100644 --- a/tests/app/celery/test_tasks.py +++ b/tests/app/celery/test_tasks.py @@ -1,6 +1,7 @@ import uuid import pytest from flask import current_app +from mock import ANY from notifications_utils.recipients import validate_phone_number, format_phone_number from app.celery.tasks import ( @@ -104,6 +105,7 @@ def test_should_call_delete_invotations_on_delete_invitations_task(notify_api, m @freeze_time("2016-01-01 11:09:00.061258") def test_should_process_sms_job(sample_job, mocker, mock_celery_remove_job): mocker.patch('app.statsd_client.incr') + mocker.patch('app.statsd_client.timing') mocker.patch('app.celery.tasks.s3.get_job_from_s3', return_value=load_example_csv('sms')) mocker.patch('app.celery.tasks.send_sms.apply_async') mocker.patch('app.encryption.encrypt', return_value="something_encrypted") @@ -126,6 +128,7 @@ def test_should_process_sms_job(sample_job, mocker, mock_celery_remove_job): job = jobs_dao.dao_get_job_by_id(sample_job.id) assert job.status == 'finished' statsd_client.incr.assert_called_once_with("notifications.tasks.process-job") + statsd_client.timing.assert_called_once_with("notifications.tasks.process-job.task-time", ANY) @freeze_time("2016-01-01 11:09:00.061258") @@ -333,6 +336,7 @@ def test_should_send_template_to_correct_sms_provider_and_persist(sample_templat mocker.patch('app.mmg_client.get_name', return_value="mmg") mocker.patch('app.statsd_client.incr') mocker.patch('app.statsd_client.timing_with_dates') + mocker.patch('app.statsd_client.timing') notification_id = uuid.uuid4() @@ -357,6 +361,7 @@ def test_should_send_template_to_correct_sms_provider_and_persist(sample_templat datetime(2016, 1, 1, 11, 10, 0, 00000), datetime(2016, 1, 1, 11, 9, 0, 00000) ) + statsd_client.timing.assert_called_once_with("notifications.tasks.send-sms.task-time", ANY) mmg_client.send_sms.assert_called_once_with( to=format_phone_number(validate_phone_number("+447234123123")), @@ -561,6 +566,7 @@ def test_should_use_email_template_and_persist(sample_email_template_with_placeh mocker.patch('app.encryption.decrypt', return_value=notification) mocker.patch('app.statsd_client.incr') mocker.patch('app.statsd_client.timing_with_dates') + mocker.patch('app.statsd_client.timing') mocker.patch('app.aws_ses_client.get_name', return_value='ses') mocker.patch('app.aws_ses_client.send_email', return_value='ses') @@ -597,7 +603,7 @@ def test_should_use_email_template_and_persist(sample_email_template_with_placeh datetime(2016, 1, 1, 11, 10, 0, 00000), datetime(2016, 1, 1, 11, 9, 0, 00000) ) - + statsd_client.timing.assert_called_once_with("notifications.tasks.send-email.task-time", ANY) persisted_notification = notifications_dao.get_notification( sample_email_template_with_placeholders.service_id, notification_id ) From 503ae80eceae3308491b9d5857bccdb8c17a7b53 Mon Sep 17 00:00:00 2001 From: Martyn Inglis Date: Mon, 16 May 2016 12:05:26 +0100 Subject: [PATCH 6/6] Dev config does not send statsd --- config.py | 4 ---- 1 file changed, 4 deletions(-) diff --git a/config.py b/config.py index fe3b983dd..b1dd2d22c 100644 --- a/config.py +++ b/config.py @@ -97,10 +97,6 @@ class Development(Config): DEBUG = True MMG_API_KEY = os.environ['MMG_API_KEY'] CSV_UPLOAD_BUCKET_NAME = 'development-notifications-csv-upload' - STATSD_ENABLED = True - STATSD_HOST = os.getenv('STATSD_HOST') - STATSD_PORT = os.getenv('STATSD_PORT') - STATSD_PREFIX = os.getenv('STATSD_PREFIX') class Preview(Config):