From f223446f7335113ad28ceb8d6529b9171674767e Mon Sep 17 00:00:00 2001 From: Martyn Inglis Date: Fri, 5 Aug 2016 10:44:43 +0100 Subject: [PATCH] Refactor statsd logging Removed all existing statsd logging and replaced with: - statsd decorator. Infers the stat name from the decorated function call. Delegates statsd call to statsd client. Calls incr and timing for each decorated method. This is applied to all tasks and all dao methods that touch the notifications/notification_history tables - statsd client changed to prefix all stats with "notification.api." - Relies on https://github.com/alphagov/notifications-utils/pull/61 for request logging. Once integrated we pass the statsd client to the logger, allowing us to statsd all API calls. This passes in the start time and the method to be called (NOT the url) onto the global flask object. We then construct statsd counters and timers in the following way notifications.api.POST.notifications.send_notification.200 This should allow us to aggregate to the level of - API or ADMIN - POST or GET etc - modules - methods - status codes Finally we count the callbacks received from 3rd parties to mapped status. --- app/__init__.py | 7 +- app/celery/provider_tasks.py | 10 +-- app/celery/scheduled_tasks.py | 6 ++ app/celery/tasks.py | 15 ++-- app/clients/statsd/statsd_client.py | 13 ++-- app/dao/notifications_dao.py | 39 +++++----- app/dao/services_dao.py | 4 ++ app/notifications/process_client_response.py | 2 +- app/notifications/rest.py | 1 - app/statsd_decorators.py | 6 +- config.py | 11 ++- tests/app/celery/test_provider_tasks.py | 72 ++----------------- tests/app/celery/test_scheduled_tasks.py | 8 +++ tests/app/celery/test_tasks.py | 26 +++---- tests/app/dao/test_services_dao.py | 6 ++ .../app/notifications/rest/test_callbacks.py | 33 --------- .../rest/test_send_notification.py | 61 +++------------- tests/app/test_statsd_decorators.py | 24 +++++++ 18 files changed, 121 insertions(+), 223 deletions(-) create mode 100644 tests/app/test_statsd_decorators.py diff --git a/app/__init__.py b/app/__init__.py index 2b1a168b7..ca2754d97 100644 --- a/app/__init__.py +++ b/app/__init__.py @@ -1,7 +1,7 @@ import uuid import os -from flask import request, url_for, g +from flask import request, url_for, g, current_app from flask import Flask, _request_ctx_stack from flask.ext.sqlalchemy import SQLAlchemy from flask_marshmallow import Marshmallow @@ -48,8 +48,8 @@ def create_app(app_name=None): init_app(application) db.init_app(application) ma.init_app(application) - logging.init_app(application) statsd_client.init_app(application) + logging.init_app(application, statsd_client) firetext_client.init_app(application, statsd_client=statsd_client) loadtest_client.init_app(application, statsd_client=statsd_client) mmg_client.init_app(application, statsd_client=statsd_client) @@ -107,8 +107,9 @@ def init_app(app): return error @app.before_request - def record_start_time(): + def record_request_details(): g.start = monotonic() + g.endpoint = request.endpoint @app.after_request def after_request(response): diff --git a/app/celery/provider_tasks.py b/app/celery/provider_tasks.py index d485e3560..afd1a4913 100644 --- a/app/celery/provider_tasks.py +++ b/app/celery/provider_tasks.py @@ -24,6 +24,7 @@ from notifications_utils.template import Template from notifications_utils.renderers import HTMLEmail, PlainTextEmail, SMSMessage from app.models import SMS_TYPE, EMAIL_TYPE, KEY_TYPE_TEST +from app.statsd_decorators import statsd def retry_iteration_to_delay(retry=0): @@ -50,9 +51,8 @@ def retry_iteration_to_delay(retry=0): @notify_celery.task(bind=True, name="send-sms-to-provider", max_retries=5, default_retry_delay=5) +@statsd(namespace="tasks") def send_sms_to_provider(self, service_id, notification_id): - task_start = monotonic() - service = dao_fetch_service_by_id(service_id) provider = provider_to_use(SMS_TYPE, notification_id) notification = get_notification_by_id(notification_id) @@ -101,8 +101,6 @@ def send_sms_to_provider(self, service_id, notification_id): current_app.logger.info( "SMS {} sent to provider at {}".format(notification_id, notification.sent_at) ) - statsd_client.incr("notifications.tasks.send-sms-to-provider") - statsd_client.timing("notifications.tasks.send-sms-to-provider.task-time", monotonic() - task_start) delta_milliseconds = (datetime.utcnow() - notification.created_at).total_seconds() * 1000 statsd_client.timing("notifications.sms.total-time", delta_milliseconds) @@ -122,8 +120,8 @@ def provider_to_use(notification_type, notification_id): @notify_celery.task(bind=True, name="send-email-to-provider", max_retries=5, default_retry_delay=5) +@statsd(namespace="tasks") def send_email_to_provider(self, service_id, notification_id): - task_start = monotonic() service = dao_fetch_service_by_id(service_id) provider = provider_to_use(EMAIL_TYPE, notification_id) notification = get_notification_by_id(notification_id) @@ -183,7 +181,5 @@ def send_email_to_provider(self, service_id, notification_id): current_app.logger.info( "Email {} sent to provider at {}".format(notification_id, notification.sent_at) ) - statsd_client.incr("notifications.tasks.send-email-to-provider") - statsd_client.timing("notifications.tasks.send-email-to-provider.task-time", monotonic() - task_start) delta_milliseconds = (datetime.utcnow() - notification.created_at).total_seconds() * 1000 statsd_client.timing("notifications.email.total-time", delta_milliseconds) diff --git a/app/celery/scheduled_tasks.py b/app/celery/scheduled_tasks.py index a1145a0f3..5606ecb2d 100644 --- a/app/celery/scheduled_tasks.py +++ b/app/celery/scheduled_tasks.py @@ -9,9 +9,11 @@ from app.dao.invited_user_dao import delete_invitations_created_more_than_two_da from app.dao.notifications_dao import delete_notifications_created_more_than_a_week_ago, get_notifications, \ update_notification_status_by_id from app.dao.users_dao import delete_codes_older_created_more_than_a_day_ago +from app.statsd_decorators import statsd @notify_celery.task(name="delete-verify-codes") +@statsd(namespace="tasks") def delete_verify_codes(): try: start = datetime.utcnow() @@ -25,6 +27,7 @@ def delete_verify_codes(): @notify_celery.task(name="delete-successful-notifications") +@statsd(namespace="tasks") def delete_successful_notifications(): try: start = datetime.utcnow() @@ -42,6 +45,7 @@ def delete_successful_notifications(): @notify_celery.task(name="delete-failed-notifications") +@statsd(namespace="tasks") def delete_failed_notifications(): try: start = datetime.utcnow() @@ -62,6 +66,7 @@ def delete_failed_notifications(): @notify_celery.task(name="delete-invitations") +@statsd(namespace="tasks") def delete_invitations(): try: start = datetime.utcnow() @@ -75,6 +80,7 @@ def delete_invitations(): @notify_celery.task(name='timeout-sending-notifications') +@statsd(namespace="tasks") def timeout_notifications(): # TODO: optimize the query by adding the date where clause to this query. notifications = get_notifications(filter_dict={'status': 'sending'}) diff --git a/app/celery/tasks.py b/app/celery/tasks.py index 6c9706ec8..bdcb37327 100644 --- a/app/celery/tasks.py +++ b/app/celery/tasks.py @@ -10,7 +10,6 @@ from notifications_utils.recipients import ( from notifications_utils.template import Template from sqlalchemy.exc import SQLAlchemyError -from app import statsd_client from app import ( create_uuid, DATETIME_FORMAT, @@ -36,11 +35,12 @@ from app.models import ( SMS_TYPE, KEY_TYPE_NORMAL ) +from app.statsd_decorators import statsd @notify_celery.task(name="process-job") +@statsd(namespace="tasks") def process_job(job_id): - task_start = monotonic() start = datetime.utcnow() job = dao_get_job_by_id(job_id) @@ -116,11 +116,10 @@ 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") - statsd_client.timing("notifications.tasks.process-job.task-time", monotonic() - task_start) @notify_celery.task(name="remove-job") +@statsd(namespace="tasks") def remove_job(job_id): job = dao_get_job_by_id(job_id) s3.remove_job_from_s3(job.service.id, str(job_id)) @@ -128,6 +127,7 @@ def remove_job(job_id): @notify_celery.task(bind=True, name="send-sms", max_retries=5, default_retry_delay=5) +@statsd(namespace="tasks") def send_sms(self, service_id, notification_id, @@ -135,7 +135,6 @@ def send_sms(self, created_at, api_key_id=None, key_type=KEY_TYPE_NORMAL): - task_start = monotonic() notification = encryption.decrypt(encrypted_notification) service = dao_fetch_service_by_id(service_id) @@ -154,21 +153,19 @@ def send_sms(self, "SMS {} created at {}".format(notification_id, created_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) raise self.retry(queue="retry", exc=e) @notify_celery.task(bind=True, name="send-email", max_retries=5, default_retry_delay=5) +@statsd(namespace="tasks") def send_email(self, service_id, notification_id, encrypted_notification, created_at, api_key_id=None, key_type=KEY_TYPE_NORMAL): - task_start = monotonic() notification = encryption.decrypt(encrypted_notification) service = dao_fetch_service_by_id(service_id) @@ -182,8 +179,6 @@ def send_email(self, service_id, send_email_to_provider.apply_async((service_id, notification_id), queue='email') current_app.logger.info("Email {} created at {}".format(notification_id, created_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) raise self.retry(queue="retry", exc=e) diff --git a/app/clients/statsd/statsd_client.py b/app/clients/statsd/statsd_client.py index 986aa2628..7bb43c0c5 100644 --- a/app/clients/statsd/statsd_client.py +++ b/app/clients/statsd/statsd_client.py @@ -10,16 +10,15 @@ class StatsdClient(StatsClient): prefix=app.config.get('STATSD_PREFIX') ) self.active = app.config.get('STATSD_ENABLED') + self.namespace = "notifications.api." + + def format_stat_name(self, stat): + return self.namespace + stat def incr(self, stat, count=1, rate=1): if self.active: - super(StatsClient, self).incr(stat, count, rate) + super(StatsClient, self).incr(self.format_stat_name(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) + super(StatsClient, self).timing(self.format_stat_name(stat), delta, rate) diff --git a/app/dao/notifications_dao.py b/app/dao/notifications_dao.py index 9f79a36de..739060d14 100644 --- a/app/dao/notifications_dao.py +++ b/app/dao/notifications_dao.py @@ -31,9 +31,10 @@ from app.clients import ( STATISTICS_REQUESTED ) from app.dao.dao_utils import transactional -from app.statsd_decorators import statsd_timer +from app.statsd_decorators import statsd -@statsd_timer(namespace="dao") + +@statsd(namespace="dao") def dao_get_notification_statistics_for_service(service_id, limit_days=None): query_filter = [NotificationStatistics.service_id == service_id] if limit_days is not None: @@ -45,7 +46,7 @@ def dao_get_notification_statistics_for_service(service_id, limit_days=None): ).all() -@statsd_timer(namespace="dao") +@statsd(namespace="dao") def dao_get_notification_statistics_for_service_and_day(service_id, day): return NotificationStatistics.query.filter_by( service_id=service_id, @@ -53,12 +54,12 @@ def dao_get_notification_statistics_for_service_and_day(service_id, day): ).order_by(desc(NotificationStatistics.day)).first() -@statsd_timer(namespace="dao") +@statsd(namespace="dao") def dao_get_notification_statistics_for_day(day): return NotificationStatistics.query.filter_by(day=day).all() -@statsd_timer(namespace="dao") +@statsd(namespace="dao") def dao_get_potential_notification_statistics_for_day(day): all_services = db.session.query( Service.id, @@ -106,7 +107,7 @@ def create_notification_statistics_dict(service_id, day): } -@statsd_timer(namespace="dao") +@statsd(namespace="dao") def dao_get_7_day_agg_notification_statistics_for_service(service_id, date_from, week_count=52): @@ -134,7 +135,7 @@ def dao_get_7_day_agg_notification_statistics_for_service(service_id, ) -@statsd_timer(namespace="dao") +@statsd(namespace="dao") def dao_get_template_statistics_for_service(service_id, limit_days=None): query_filter = [TemplateStatistics.service_id == service_id] if limit_days is not None: @@ -143,7 +144,7 @@ def dao_get_template_statistics_for_service(service_id, limit_days=None): desc(TemplateStatistics.updated_at)).all() -@statsd_timer(namespace="dao") +@statsd(namespace="dao") def dao_get_template_statistics_for_template(template_id): return TemplateStatistics.query.filter( TemplateStatistics.template_id == template_id @@ -152,7 +153,7 @@ def dao_get_template_statistics_for_template(template_id): ).all() -@statsd_timer(namespace="dao") +@statsd(namespace="dao") @transactional def dao_create_notification(notification, notification_type): if notification.job_id: @@ -260,7 +261,7 @@ def _update_notification_status(notification, status, notification_statistics_st return True -@statsd_timer(namespace="dao") +@statsd(namespace="dao") @transactional def update_notification_status_by_id(notification_id, status, notification_statistics_status=None): notification = Notification.query.with_lockmode("update").filter( @@ -279,7 +280,7 @@ def update_notification_status_by_id(notification_id, status, notification_stati ) -@statsd_timer(namespace="dao") +@statsd(namespace="dao") @transactional def update_notification_status_by_reference(reference, status, notification_statistics_status): notification = Notification.query.filter(Notification.reference == reference, @@ -296,7 +297,7 @@ def update_notification_status_by_reference(reference, status, notification_stat ) -@statsd_timer(namespace="dao") +@statsd(namespace="dao") def dao_update_notification(notification): notification.updated_at = datetime.utcnow() notification_history = NotificationHistory.query.get(notification.id) @@ -305,7 +306,7 @@ def dao_update_notification(notification): db.session.commit() -@statsd_timer(namespace="dao") +@statsd(namespace="dao") @transactional def update_provider_stats( id_, @@ -340,12 +341,12 @@ def update_provider_stats( db.session.add(provider_stats) -@statsd_timer(namespace="dao") +@statsd(namespace="dao") def get_notification_for_job(service_id, job_id, notification_id): return Notification.query.filter_by(service_id=service_id, job_id=job_id, id=notification_id).one() -@statsd_timer(namespace="dao") +@statsd(namespace="dao") def get_notifications_for_job(service_id, job_id, filter_dict=None, page=1, page_size=None): if page_size is None: page_size = current_app.config['PAGE_SIZE'] @@ -357,7 +358,7 @@ def get_notifications_for_job(service_id, job_id, filter_dict=None, page=1, page ) -@statsd_timer(namespace="dao") +@statsd(namespace="dao") def get_notification(service_id, notification_id, key_type=None): filter_dict = {'service_id': service_id, 'id': notification_id} if key_type: @@ -366,7 +367,7 @@ def get_notification(service_id, notification_id, key_type=None): return Notification.query.filter_by(**filter_dict).one() -@statsd_timer(namespace="dao") +@statsd(namespace="dao") def get_notification_by_id(notification_id): return Notification.query.filter_by(id=notification_id).first() @@ -375,7 +376,7 @@ def get_notifications(filter_dict=None): return _filter_query(Notification.query, filter_dict=filter_dict) -@statsd_timer(namespace="dao") +@statsd(namespace="dao") def get_notifications_for_service(service_id, filter_dict=None, page=1, @@ -415,7 +416,7 @@ def _filter_query(query, filter_dict=None): return query -@statsd_timer(namespace="dao") +@statsd(namespace="dao") def delete_notifications_created_more_than_a_week_ago(status): seven_days_ago = date.today() - timedelta(days=7) deleted = db.session.query(Notification).filter( diff --git a/app/dao/services_dao.py b/app/dao/services_dao.py index a16aff007..5bd2e975a 100644 --- a/app/dao/services_dao.py +++ b/app/dao/services_dao.py @@ -24,6 +24,7 @@ from app.models import ( InvitedUser, Service ) +from app.statsd_decorators import statsd def dao_fetch_all_services(): @@ -136,10 +137,12 @@ def delete_service_and_all_associated_db_objects(service): db.session.commit() +@statsd(namespace="dao") def dao_fetch_stats_for_service(service_id): return _stats_for_service_query(service_id).all() +@statsd(namespace="dao") def dao_fetch_todays_stats_for_service(service_id): return _stats_for_service_query(service_id).filter( func.date(Notification.created_at) == date.today() @@ -159,6 +162,7 @@ def _stats_for_service_query(service_id): ) +@statsd(namespace="dao") def dao_fetch_weekly_historical_stats_for_service(service_id): monday_of_notification_week = func.date_trunc('week', NotificationHistory.created_at).label('week_start') return db.session.query( diff --git a/app/notifications/process_client_response.py b/app/notifications/process_client_response.py index aafc88659..595fbcd4d 100644 --- a/app/notifications/process_client_response.py +++ b/app/notifications/process_client_response.py @@ -39,7 +39,7 @@ def process_sms_client_response(status, reference, client_name): except KeyError: return success, 'unknown sms client: {}'.format(client_name) - statsd_client.incr('notifications.callback.{}.status.{}'.format(client_name.lower(), status)) + statsd_client.incr('callback.{}.status.{}'.format(client_name.lower(), status)) # validate status try: diff --git a/app/notifications/rest.py b/app/notifications/rest.py index 897dbc456..89d481a8b 100644 --- a/app/notifications/rest.py +++ b/app/notifications/rest.py @@ -158,7 +158,6 @@ def process_firetext_response(): response_code = request.form.get('code') status = request.form.get('status') - statsd_client.incr('notifications.callback.firetext.code.{}'.format(response_code)) current_app.logger.info('Firetext status: {}, extended error code: {}'.format(status, response_code)) success, errors = process_sms_client_response(status=status, diff --git a/app/statsd_decorators.py b/app/statsd_decorators.py index b379d9430..2f83f13b6 100644 --- a/app/statsd_decorators.py +++ b/app/statsd_decorators.py @@ -5,7 +5,7 @@ from flask import current_app from monotonic import monotonic -def statsd_timer(namespace): +def statsd(namespace): def time_function(func): @functools.wraps(func) def wrapper(*args, **kwargs): @@ -17,10 +17,10 @@ def statsd_timer(namespace): namespace=namespace, func=func.__name__, time="{0:.4f}".format(elapsed_time) ) ) - statsd_client.incr('notifications.{namespace}.{func}'.format( + statsd_client.incr('{namespace}.{func}'.format( namespace=namespace, func=func.__name__) ) - statsd_client.timing('notifications.{namespace}.{func}'.format( + statsd_client.timing('{namespace}.{func}'.format( namespace=namespace, func=func.__name__), elapsed_time ) return res diff --git a/config.py b/config.py index c15993e97..dcb5b92f1 100644 --- a/config.py +++ b/config.py @@ -102,32 +102,39 @@ class Config(object): FROM_NUMBER = os.getenv('FROM_NUMBER') STATSD_ENABLED = False - STATSD_HOST = "localhost" - STATSD_PORT = None + STATSD_HOST = "statsd.hostedgraphite.com" + STATSD_PORT = 8125 STATSD_PREFIX = None SENDING_NOTIFICATIONS_TIMEOUT_PERIOD = 259200 class Development(Config): + CSV_UPLOAD_BUCKET_NAME = 'developement-martyn-notifications-csv-upload' DEBUG = True class Preview(Config): CSV_UPLOAD_BUCKET_NAME = 'preview-notifications-csv-upload' + STATSD_PREFIX = "preview" class Test(Development): CSV_UPLOAD_BUCKET_NAME = 'test-notifications-csv-upload' + STATSD_PREFIX = "test" class Staging(Config): CSV_UPLOAD_BUCKET_NAME = 'staging-notify-csv-upload' + STATSD_PREFIX = os.getenv('STATSD_PREFIX') + STATSD_ENABLED = True class Live(Config): CSV_UPLOAD_BUCKET_NAME = 'live-notifications-csv-upload' STATSD_ENABLED = True + STATSD_PREFIX = os.getenv('STATSD_PREFIX') + STATSD_ENABLED = True configs = { diff --git a/tests/app/celery/test_provider_tasks.py b/tests/app/celery/test_provider_tasks.py index 64d1d296d..0322197d8 100644 --- a/tests/app/celery/test_provider_tasks.py +++ b/tests/app/celery/test_provider_tasks.py @@ -20,6 +20,11 @@ from app.models import Notification, NotificationStatistics, Job, KEY_TYPE_NORMA from tests.app.conftest import sample_notification +def test_should_have_decorated_tasks_functions(): + assert send_sms_to_provider.__wrapped__.__name__ == 'send_sms_to_provider' + assert send_email_to_provider.__wrapped__.__name__ == 'send_email_to_provider' + + def test_should_by_10_second_delay_as_default(): assert provider_tasks.retry_iteration_to_delay() == 10 @@ -91,9 +96,6 @@ def test_should_send_personalised_template_to_correct_sms_provider_and_persist( 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') - mocker.patch('app.statsd_client.timing') send_sms_to_provider( db_notification.service_id, @@ -130,9 +132,6 @@ def test_should_send_personalised_template_to_correct_email_provider_and_persist mocker.patch('app.aws_ses_client.send_email', return_value='reference') mocker.patch('app.aws_ses_client.get_name', return_value="ses") - mocker.patch('app.statsd_client.incr') - mocker.patch('app.statsd_client.timing_with_dates') - mocker.patch('app.statsd_client.timing') send_email_to_provider( db_notification.service_id, @@ -297,29 +296,6 @@ def test_should_not_send_to_provider_when_status_is_not_created(notify_db, notif app.celery.research_mode_tasks.send_sms_response.apply_async.assert_not_called() -def test_send_sms_statsd_updates(notify_db, notify_db_session, sample_service, sample_notification, mocker): - mocker.patch('app.statsd_client.incr') - mocker.patch('app.statsd_client.timing') - mocker.patch('app.mmg_client.send_sms') - mocker.patch('app.mmg_client.get_name', return_value="mmg") - - send_sms_to_provider( - sample_notification.service_id, - sample_notification.id - ) - - statsd_client.incr.assert_called_once_with("notifications.tasks.send-sms-to-provider") - - statsd_client.timing.assert_has_calls([ - call("notifications.tasks.send-sms-to-provider.task-time", ANY), - call("notifications.sms.total-time", ANY) - ]) - - # assert that the ANYs above are at least floats - for call_arg in statsd_client.timing.call_args_list: - assert isinstance(call_arg[0][1], float) - - def test_should_go_into_technical_error_if_exceeds_retries( notify_db, notify_db_session, @@ -329,8 +305,6 @@ def test_should_go_into_technical_error_if_exceeds_retries( notification = sample_notification(notify_db=notify_db, notify_db_session=notify_db_session, service=sample_service, status='created') - mocker.patch('app.statsd_client.incr') - mocker.patch('app.statsd_client.timing') mocker.patch('app.mmg_client.send_sms', side_effect=SmsClientException("EXPECTED")) mocker.patch('app.celery.provider_tasks.send_sms_to_provider.retry', side_effect=MaxRetriesExceededError()) @@ -340,8 +314,6 @@ def test_should_go_into_technical_error_if_exceeds_retries( ) provider_tasks.send_sms_to_provider.retry.assert_called_with(queue='retry', countdown=10) - assert statsd_client.incr.assert_not_called - assert statsd_client.timing.assert_not_called db_notification = Notification.query.filter_by(id=notification.id).one() assert db_notification.status == 'technical-failure' @@ -369,9 +341,6 @@ def test_should_send_sms_sender_from_service_if_present( 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') - mocker.patch('app.statsd_client.timing') send_sms_to_provider( db_notification.service_id, @@ -450,8 +419,6 @@ def test_send_email_to_provider_should_go_into_technical_error_if_exceeds_retrie notification = sample_notification(notify_db=notify_db, notify_db_session=notify_db_session, service=sample_service, status='created', template=sample_email_template) - mocker.patch('app.statsd_client.incr') - mocker.patch('app.statsd_client.timing') mocker.patch('app.aws_ses_client.send_email', side_effect=EmailClientException("EXPECTED")) mocker.patch('app.celery.provider_tasks.send_email_to_provider.retry', side_effect=MaxRetriesExceededError()) @@ -461,8 +428,6 @@ def test_send_email_to_provider_should_go_into_technical_error_if_exceeds_retrie ) provider_tasks.send_email_to_provider.retry.assert_called_with(queue='retry', countdown=10) - assert statsd_client.incr.assert_not_called - assert statsd_client.timing.assert_not_called db_notification = Notification.query.filter_by(id=notification.id).one() assert db_notification.status == 'technical-failure' @@ -474,31 +439,6 @@ def test_send_email_to_provider_should_go_into_technical_error_if_exceeds_retrie assert job.notifications_failed == 1 -def test_send_email_to_provider_statsd_updates(notify_db, notify_db_session, sample_service, - sample_email_template, mocker): - mocker.patch('app.statsd_client.incr') - mocker.patch('app.statsd_client.timing') - mocker.patch('app.aws_ses_client.send_email', return_value='reference') - mocker.patch('app.aws_ses_client.get_name', return_value="ses") - notification = sample_notification(notify_db=notify_db, notify_db_session=notify_db_session, - template=sample_email_template) - send_email_to_provider( - notification.service_id, - notification.id - ) - - statsd_client.incr.assert_called_once_with("notifications.tasks.send-email-to-provider") - - statsd_client.timing.assert_has_calls([ - call("notifications.tasks.send-email-to-provider.task-time", ANY), - call("notifications.email.total-time", ANY) - ]) - - # assert that the ANYs above are at least floats - for call_arg in statsd_client.timing.call_args_list: - assert isinstance(call_arg[0][1], float) - - def test_send_email_to_provider_should_not_send_to_provider_when_status_is_not_created(notify_db, notify_db_session, sample_service, sample_email_template, @@ -525,8 +465,6 @@ def test_send_email_should_use_service_reply_to_email( sample_service, sample_email_template, mocker): - mocker.patch('app.statsd_client.incr') - mocker.patch('app.statsd_client.timing') mocker.patch('app.aws_ses_client.send_email', return_value='reference') mocker.patch('app.aws_ses_client.get_name', return_value="ses") diff --git a/tests/app/celery/test_scheduled_tasks.py b/tests/app/celery/test_scheduled_tasks.py index 9c477918d..0564b1712 100644 --- a/tests/app/celery/test_scheduled_tasks.py +++ b/tests/app/celery/test_scheduled_tasks.py @@ -11,6 +11,14 @@ from app.celery.scheduled_tasks import (delete_verify_codes, from tests.app.conftest import sample_notification +def test_should_have_decorated_tasks_functions(): + assert delete_verify_codes.__wrapped__.__name__ == 'delete_verify_codes' + assert delete_successful_notifications.__wrapped__.__name__ == 'delete_successful_notifications' + assert delete_failed_notifications.__wrapped__.__name__ == 'delete_failed_notifications' + assert timeout_notifications.__wrapped__.__name__ == 'timeout_notifications' + assert delete_invitations.__wrapped__.__name__ == 'delete_invitations' + + def test_should_call_delete_notifications_more_than_week_in_task(notify_api, mocker): mocked = mocker.patch('app.celery.scheduled_tasksgit .delete_notifications_created_more_than_a_week_ago') delete_successful_notifications() diff --git a/tests/app/celery/test_tasks.py b/tests/app/celery/test_tasks.py index ab6a6cafb..547ee769e 100644 --- a/tests/app/celery/test_tasks.py +++ b/tests/app/celery/test_tasks.py @@ -7,10 +7,10 @@ from mock import ANY from sqlalchemy.exc import SQLAlchemyError from sqlalchemy.orm.exc import NoResultFound -from app import (encryption, DATETIME_FORMAT, statsd_client) +from app import (encryption, DATETIME_FORMAT) from app.celery import provider_tasks from app.celery import tasks -from app.celery.tasks import s3 +from app.celery.tasks import s3, remove_job from app.celery.tasks import ( send_sms, process_job, @@ -53,10 +53,15 @@ def _notification_json(template, to, personalisation=None, job_id=None, row_numb return notification +def test_should_have_decorated_tasks_functions(): + assert process_job.__wrapped__.__name__ == 'process_job' + assert remove_job.__wrapped__.__name__ == 'remove_job' + assert send_sms.__wrapped__.__name__ == 'send_sms' + assert send_email.__wrapped__.__name__ == 'send_email' + + @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") @@ -81,8 +86,6 @@ 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") @@ -278,9 +281,6 @@ def test_should_send_template_to_correct_sms_task_and_persist(sample_template_wi notification = _notification_json(sample_template_with_placeholders, to="+447234123123", personalisation={"name": "Jo"}) - mocker.patch('app.statsd_client.incr') - mocker.patch('app.statsd_client.timing_with_dates') - mocker.patch('app.statsd_client.timing') mocker.patch('app.celery.provider_tasks.send_sms_to_provider.apply_async') notification_id = uuid.uuid4() @@ -292,15 +292,12 @@ def test_should_send_template_to_correct_sms_task_and_persist(sample_template_wi datetime.utcnow().strftime(DATETIME_FORMAT) ) - statsd_client.timing.assert_called_once_with("notifications.tasks.send-sms.task-time", ANY) - provider_tasks.send_sms_to_provider.apply_async.assert_called_once_with( (sample_template_with_placeholders.service_id, notification_id), queue="sms" ) - statsd_client.incr.assert_called_once_with("notifications.tasks.send-sms") persisted_notification = Notification.query.filter_by(id=notification_id).one() assert persisted_notification.id == notification_id assert persisted_notification.to == '+447234123123' @@ -436,9 +433,6 @@ def test_should_use_email_template_and_persist(sample_email_template_with_placeh "my_email@my_email.com", {"name": "Jo"}, row_number=1) - mocker.patch('app.statsd_client.incr') - mocker.patch('app.statsd_client.timing_with_dates') - mocker.patch('app.statsd_client.timing') mocker.patch('app.celery.provider_tasks.send_email_to_provider.apply_async') notification_id = uuid.uuid4() @@ -456,8 +450,6 @@ def test_should_use_email_template_and_persist(sample_email_template_with_placeh key_type=KEY_TYPE_TEAM ) - statsd_client.incr.assert_called_once_with("notifications.tasks.send-email") - statsd_client.timing.assert_called_once_with("notifications.tasks.send-email.task-time", ANY) persisted_notification = Notification.query.filter_by(id=notification_id).one() provider_tasks.send_email_to_provider.apply_async.assert_called_once_with( (sample_email_template_with_placeholders.service_id, notification_id), queue='email') diff --git a/tests/app/dao/test_services_dao.py b/tests/app/dao/test_services_dao.py index 4369c1c4f..943343b61 100644 --- a/tests/app/dao/test_services_dao.py +++ b/tests/app/dao/test_services_dao.py @@ -44,6 +44,12 @@ from tests.app.conftest import ( ) +def test_should_have_decorated_services_dao_functions(): + assert dao_fetch_weekly_historical_stats_for_service.__wrapped__.__name__ == 'dao_fetch_weekly_historical_stats_for_service' # noqa + assert dao_fetch_todays_stats_for_service.__wrapped__.__name__ == 'dao_fetch_todays_stats_for_service' # noqa + assert dao_fetch_stats_for_service.__wrapped__.__name__ == 'dao_fetch_stats_for_service' # noqa + + def test_create_service(sample_user): assert Service.query.count() == 0 service = Service(name="service_name", diff --git a/tests/app/notifications/rest/test_callbacks.py b/tests/app/notifications/rest/test_callbacks.py index b173fc90d..f045817a2 100644 --- a/tests/app/notifications/rest/test_callbacks.py +++ b/tests/app/notifications/rest/test_callbacks.py @@ -542,34 +542,6 @@ def test_ses_callback_should_update_multiple_notification_status_sent( assert stats.emails_failed == 0 -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', - status='sending' - ) - - 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_ses_callback_should_set_status_to_temporary_failure(notify_api, notify_db, notify_db_session, @@ -707,9 +679,7 @@ def test_process_mmg_response_records_statsd(notify_api, sample_notification, mo client.post(path='notifications/sms/mmg', data=data, headers=[('Content-Type', 'application/json')]) - assert app.statsd_client.incr.call_count == 2 app.statsd_client.incr.assert_any_call("notifications.callback.mmg.delivered") - app.statsd_client.incr.assert_any_call("notifications.callback.mmg.status.3") def test_firetext_callback_should_record_statsd(notify_api, notify_db, notify_db_session, mocker): @@ -725,9 +695,6 @@ def test_firetext_callback_should_record_statsd(notify_api, notify_db, notify_db ), headers=[('Content-Type', 'application/x-www-form-urlencoded')]) - assert app.statsd_client.incr.call_count == 3 - app.statsd_client.incr.assert_any_call("notifications.callback.firetext.code.101") - app.statsd_client.incr.assert_any_call("notifications.callback.firetext.status.0") app.statsd_client.incr.assert_any_call("notifications.callback.firetext.delivered") diff --git a/tests/app/notifications/rest/test_send_notification.py b/tests/app/notifications/rest/test_send_notification.py index 301c67ecf..c201a11d0 100644 --- a/tests/app/notifications/rest/test_send_notification.py +++ b/tests/app/notifications/rest/test_send_notification.py @@ -10,7 +10,7 @@ from notifications_python_client.authentication import create_jwt_token import app from app import encryption -from app.models import ApiKey, KEY_TYPE_TEAM, KEY_TYPE_TEST +from app.models import ApiKey, KEY_TYPE_TEAM from app.dao.templates_dao import dao_get_all_templates_for_service, dao_update_template from app.dao.services_dao import dao_update_service from app.dao.api_key_dao import save_model_api_key @@ -37,7 +37,6 @@ def test_create_sms_should_reject_if_missing_required_fields(notify_api, sample_ headers=[('Content-Type', 'application/json'), auth_header]) json_resp = json.loads(response.get_data(as_text=True)) - app.celery.tasks.send_sms.apply_async.assert_not_called() assert json_resp['result'] == 'error' assert 'Missing data for required field.' in json_resp['message']['to'][0] assert 'Missing data for required field.' in json_resp['message']['template'][0] @@ -313,13 +312,13 @@ def test_should_not_allow_template_from_another_service(notify_api, service_fact ] ) def test_should_not_allow_template_content_too_large( - notify_api, - notify_db, - notify_db_session, - sample_user, - template_type, - mocker, - should_error + notify_api, + notify_db, + notify_db_session, + sample_user, + template_type, + mocker, + should_error ): with notify_api.test_request_context(): with notify_api.test_client() as client: @@ -655,50 +654,6 @@ def test_should_allow_api_call_if_under_day_limit_regardless_of_type(notify_db, assert response.status_code == 201 -def test_should_record_email_request_in_statsd(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') - 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("notifications.api.email") - - -def test_should_record_sms_request_in_statsd(notify_api, 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("notifications.api.sms") - - def test_should_not_return_html_in_body(notify_api, notify_db, notify_db_session, mocker): with notify_api.test_request_context(): with notify_api.test_client() as client: diff --git a/tests/app/test_statsd_decorators.py b/tests/app/test_statsd_decorators.py new file mode 100644 index 000000000..3470f9038 --- /dev/null +++ b/tests/app/test_statsd_decorators.py @@ -0,0 +1,24 @@ +from mock import ANY + +from app.statsd_decorators import statsd +import app + + +class AnyStringWith(str): + def __eq__(self, other): + return self in other + + +def test_should_call_statsd(notify_api, mocker): + mocker.patch('app.statsd_client.incr') + mocker.patch('app.statsd_client.timing') + mock_logger = mocker.patch.object(notify_api.logger, 'info') + + @statsd(namespace="test") + def test_function(): + return True + + assert test_function() + app.statsd_client.incr.assert_called_once_with("test.test_function") + app.statsd_client.timing.assert_called_once_with("test.test_function", ANY) + mock_logger.assert_called_once_with(AnyStringWith("test call test_function took "))