Merge pull request #1622 from alphagov/reduce-logging

Reducing the logging for the life cycle of a notification

app/celery/tasks.py

@@ -110,7 +110,7 @@ def process_job(job_id):
     TemplateClass = get_template_class(db_template.template_type)
     template = TemplateClass(db_template.__dict__)
 
-    current_app.logger.info("Starting job {} processing {} notifications".format(job_id, job.notification_count))
+    current_app.logger.debug("Starting job {} processing {} notifications".format(job_id, job.notification_count))
 
     for row_number, recipient, personalisation in RecipientCSV(
             s3.get_job_from_s3(str(service.id), str(job_id)),
@@ -131,7 +131,7 @@ def job_complete(job, service, template_type, resumed=False, start=None):
             update_job_to_sent_to_dvla.apply_async([str(job.id)], queue=QueueNames.RESEARCH_MODE)
         else:
             build_dvla_file.apply_async([str(job.id)], queue=QueueNames.JOBS)
-            current_app.logger.info("send job {} to build-dvla-file in the {} queue".format(job.id, QueueNames.JOBS))
+            current_app.logger.debug("send job {} to build-dvla-file in the {} queue".format(job.id, QueueNames.JOBS))
     else:
         job.job_status = JOB_STATUS_FINISHED
 
@@ -206,7 +206,7 @@ def save_sms(self,
     template = dao_get_template_by_id(notification['template'], version=notification['template_version'])
 
     if not service_allowed_to_send_to(notification['to'], service, key_type):
-        current_app.logger.info(
+        current_app.logger.debug(
             "SMS {} failed as restricted service".format(notification_id)
         )
         return
@@ -233,7 +233,7 @@ def save_sms(self,
             queue=QueueNames.SEND_SMS if not service.research_mode else QueueNames.RESEARCH_MODE
         )
 
-        current_app.logger.info(
+        current_app.logger.debug(
             "SMS {} created at {} for job {}".format(
                 saved_notification.id,
                 saved_notification.created_at,
@@ -283,7 +283,7 @@ def save_email(self,
             queue=QueueNames.SEND_EMAIL if not service.research_mode else QueueNames.RESEARCH_MODE
         )
 
-        current_app.logger.info("Email {} created at {}".format(saved_notification.id, saved_notification.created_at))
+        current_app.logger.debug("Email {} created at {}".format(saved_notification.id, saved_notification.created_at))
     except SQLAlchemyError as e:
         handle_exception(self, notification, notification_id, e)
 
@@ -340,7 +340,7 @@ def save_letter(
             else:
                 update_notification_status_by_reference(saved_notification.reference, 'delivered')
 
-        current_app.logger.info("Letter {} created at {}".format(saved_notification.id, saved_notification.created_at))
+        current_app.logger.debug("Letter {} created at {}".format(saved_notification.id, saved_notification.created_at))
     except SQLAlchemyError as e:
         handle_exception(self, notification, notification_id, e)
 
@@ -421,7 +421,7 @@ def update_letter_notifications_to_error(self, notification_references):
         }
     )
 
-    current_app.logger.info("Updated {} letter notifications to technical-failure".format(updated_count))
+    current_app.logger.debug("Updated {} letter notifications to technical-failure".format(updated_count))
 
 
 def create_dvla_file_contents_for_job(job_id):
@@ -553,7 +553,7 @@ def send_inbound_sms_to_service(self, inbound_sms_id, service_id):
             },
             timeout=60
         )
-        current_app.logger.info('send_inbound_sms_to_service sending {} to {}, response {}'.format(
+        current_app.logger.debug('send_inbound_sms_to_service sending {} to {}, response {}'.format(
             inbound_sms_id,
             inbound_api.url,
             response.status_code

app/delivery/send_to_providers.py

@@ -43,7 +43,7 @@ def send_sms_to_provider(notification):
 
     if notification.status == 'created':
         provider = provider_to_use(SMS_TYPE, notification.id, notification.international)
-        current_app.logger.info(
+        current_app.logger.debug(
             "Starting sending SMS {} to provider at {}".format(notification.id, datetime.utcnow())
         )
         template_model = dao_get_template_by_id(notification.template_id, notification.template_version)
@@ -85,7 +85,7 @@ def send_sms_to_provider(notification):
 
         create_initial_notification_statistic_tasks(notification)
 
-        current_app.logger.info(
+        current_app.logger.debug(
             "SMS {} sent to provider {} at {}".format(notification.id, provider.get_name(), notification.sent_at)
         )
         delta_milliseconds = (datetime.utcnow() - notification.created_at).total_seconds() * 1000
@@ -99,7 +99,7 @@ def send_email_to_provider(notification):
         return
     if notification.status == 'created':
         provider = provider_to_use(EMAIL_TYPE, notification.id)
-        current_app.logger.info(
+        current_app.logger.debug(
             "Starting sending EMAIL {} to provider at {}".format(notification.id, datetime.utcnow())
         )
         template_dict = dao_get_template_by_id(notification.template_id, notification.template_version).__dict__
@@ -140,7 +140,7 @@ def send_email_to_provider(notification):
 
         create_initial_notification_statistic_tasks(notification)
 
-        current_app.logger.info(
+        current_app.logger.debug(
             "Email {} sent to provider at {}".format(notification.id, notification.sent_at)
         )
         delta_milliseconds = (datetime.utcnow() - notification.created_at).total_seconds() * 1000

app/notifications/notifications_letter_callback.py

@@ -47,7 +47,7 @@ def validate_schema(schema):
 @validate_schema(dvla_sns_callback_schema)
 def process_letter_response():
     req_json = request.get_json(force=True)
-    current_app.logger.info('Received SNS callback: {}'.format(req_json))
+    current_app.logger.debug('Received SNS callback: {}'.format(req_json))
     if not autoconfirm_subscription(req_json):
         # The callback should have one record for an S3 Put Event.
         message = json.loads(req_json['Message'])

app/notifications/notifications_sms_callback.py

@@ -26,7 +26,7 @@ def process_mmg_response():
 
     safe_to_log = data.copy()
     safe_to_log.pop("MSISDN")
-    current_app.logger.info(
+    current_app.logger.debug(
         "Full delivery response from {} for notification: {}\n{}".format(client_name, request.form.get('CID'),
                                                                          safe_to_log))
     if errors:
@@ -45,7 +45,7 @@ def process_firetext_response():
         raise InvalidRequest(errors, status_code=400)
     safe_to_log = dict(request.form).copy()
     safe_to_log.pop('mobile')
-    current_app.logger.info(
+    current_app.logger.debug(
         "Full delivery response from {} for notification: {}\n{}".format(client_name, request.form.get('reference'),
                                                                          safe_to_log))
     success, errors = process_sms_client_response(status=request.form.get('status'),

app/notifications/process_client_response.py

@@ -71,7 +71,7 @@ def process_sms_client_response(status, reference, client_name):
         return success, errors
 
     if not notification_success:
-        current_app.logger.info(
+        current_app.logger.debug(
             "{} delivery failed: notification {} has error found. Status {}".format(client_name,
                                                                                     reference,
                                                                                     notification_status_message))

app/notifications/process_notifications.py

@@ -133,7 +133,7 @@ def send_notification_to_queue(notification, research_mode, queue=None):
         dao_delete_notifications_and_history_by_id(notification.id)
         raise
 
-    current_app.logger.info(
+    current_app.logger.debug(
         "{} {} sent to the {} queue for delivery".format(notification.notification_type,
                                                          notification.id,
                                                          queue))

app/notifications/receive_notifications.py

@@ -59,7 +59,7 @@ def receive_mmg_sms():
 
     tasks.send_inbound_sms_to_service.apply_async([str(inbound.id), str(service.id)], queue=QueueNames.NOTIFY)
 
-    current_app.logger.info(
+    current_app.logger.debug(
         '{} received inbound SMS with reference {} from MMG'.format(service.id, inbound.provider_reference))
     return jsonify({
         "status": "ok"
@@ -96,7 +96,7 @@ def receive_firetext_sms():
     statsd_client.incr('inbound.firetext.successful')
 
     tasks.send_inbound_sms_to_service.apply_async([str(inbound.id), str(service.id)], queue=QueueNames.NOTIFY)
-    current_app.logger.info(
+    current_app.logger.debug(
         '{} received inbound SMS with reference {} from Firetext'.format(service.id, inbound.provider_reference))
     return jsonify({
         "status": "ok"

app/notifications/rest.py

@@ -138,7 +138,7 @@ def send_notification(notification_type):
                                    research_mode=authenticated_service.research_mode,
                                    queue=queue_name)
     else:
-        current_app.logger.info("POST simulated notification for id: {}".format(notification_model.id))
+        current_app.logger.debug("POST simulated notification for id: {}".format(notification_model.id))
     notification_form.update({"template_version": template.version})
 
     return jsonify(

app/notifications/utils.py

@@ -20,6 +20,6 @@ def confirm_subscription(confirmation_request):
 
 def autoconfirm_subscription(req_json):
     if req_json.get('Type') == 'SubscriptionConfirmation':
-        current_app.logger.info("SNS subscription confirmation url: {}".format(req_json['SubscribeURL']))
+        current_app.logger.debug("SNS subscription confirmation url: {}".format(req_json['SubscribeURL']))
         subscribed_topic = confirm_subscription(req_json)
         return subscribed_topic

app/v2/notifications/post_notifications.py

@@ -161,7 +161,7 @@ def process_sms_or_email_notification(*, form, notification_type, api_key, templ
                 queue=queue_name
             )
         else:
-            current_app.logger.info("POST simulated notification for id: {}".format(notification.id))
+            current_app.logger.debug("POST simulated notification for id: {}".format(notification.id))
 
     return notification