As Notify matures we probably need less logging, especially to report happy path events.

This PR is a proposal to reduce the average messages we see for a single notification from about 7 messages to 2.

Messaging would change to something like this:
February 2nd 2018, 15:39:05.885	Full delivery response from Firetext for notification: 8eda51d5-cd82-4569-bfc9-d5570cdf2126
{'status': ['0'], 'reference': ['8eda51d5-cd82-4569-bfc9-d5570cdf2126'], 'time': ['2018-02-02 15:39:01'], 'code': ['000']}
February 2nd 2018, 15:39:05.885	Firetext callback return status of 0 for reference: 8eda51d5-cd82-4569-bfc9-d5570cdf2126
February 2nd 2018, 15:38:57.727	SMS 8eda51d5-cd82-4569-bfc9-d5570cdf2126 sent to provider firetext at 2018-02-02 15:38:56.716814
February 2nd 2018, 15:38:56.727	Starting sending SMS 8eda51d5-cd82-4569-bfc9-d5570cdf2126 to provider at 2018-02-02 15:38:56.408181
February 2nd 2018, 15:38:56.727	Firetext request for 8eda51d5-cd82-4569-bfc9-d5570cdf2126 finished in 0.30376038211397827
February 2nd 2018, 15:38:49.449	sms 8eda51d5-cd82-4569-bfc9-d5570cdf2126 created at 2018-02-02 15:38:48.439113
February 2nd 2018, 15:38:49.449	sms 8eda51d5-cd82-4569-bfc9-d5570cdf2126 sent to the priority-tasks queue for delivery

To somthing like this:
February 2nd 2018, 15:39:05.885	Firetext callback return status of 0 for reference: 8eda51d5-cd82-4569-bfc9-d5570cdf2126
February 2nd 2018, 15:38:49.449	sms 8eda51d5-cd82-4569-bfc9-d5570cdf2126 created at 2018-02-02 15:38:48.439113

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