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

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

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)

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

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)

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)

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(

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(

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:

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,

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