From dce79832fff8ba325044009484012259227754d2 Mon Sep 17 00:00:00 2001 From: Rebecca Law Date: Fri, 2 Feb 2018 15:55:25 +0000 Subject: [PATCH] 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/celery/tasks.py | 16 ++++++++-------- app/delivery/send_to_providers.py | 8 ++++---- .../notifications_letter_callback.py | 2 +- app/notifications/notifications_sms_callback.py | 4 ++-- app/notifications/process_client_response.py | 2 +- app/notifications/process_notifications.py | 2 +- app/notifications/receive_notifications.py | 4 ++-- app/notifications/rest.py | 2 +- app/notifications/utils.py | 2 +- app/v2/notifications/post_notifications.py | 2 +- 10 files changed, 22 insertions(+), 22 deletions(-) diff --git a/app/celery/tasks.py b/app/celery/tasks.py index 7063b791a..acaf12298 100644 --- a/app/celery/tasks.py +++ b/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 diff --git a/app/delivery/send_to_providers.py b/app/delivery/send_to_providers.py index b5ad59dec..16b9c9ec4 100644 --- a/app/delivery/send_to_providers.py +++ b/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 diff --git a/app/notifications/notifications_letter_callback.py b/app/notifications/notifications_letter_callback.py index ae722e017..97a6bebf2 100644 --- a/app/notifications/notifications_letter_callback.py +++ b/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']) diff --git a/app/notifications/notifications_sms_callback.py b/app/notifications/notifications_sms_callback.py index 4cf954840..950e68b7b 100644 --- a/app/notifications/notifications_sms_callback.py +++ b/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'), diff --git a/app/notifications/process_client_response.py b/app/notifications/process_client_response.py index ad78c744d..aa85f14ae 100644 --- a/app/notifications/process_client_response.py +++ b/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)) diff --git a/app/notifications/process_notifications.py b/app/notifications/process_notifications.py index 965fa7e6b..41378f8da 100644 --- a/app/notifications/process_notifications.py +++ b/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)) diff --git a/app/notifications/receive_notifications.py b/app/notifications/receive_notifications.py index cd6eda598..b73730ece 100644 --- a/app/notifications/receive_notifications.py +++ b/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" diff --git a/app/notifications/rest.py b/app/notifications/rest.py index 750505834..ff0a9db3e 100644 --- a/app/notifications/rest.py +++ b/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( diff --git a/app/notifications/utils.py b/app/notifications/utils.py index 5f1443f09..bca551749 100644 --- a/app/notifications/utils.py +++ b/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 diff --git a/app/v2/notifications/post_notifications.py b/app/v2/notifications/post_notifications.py index aa543e6c1..a619c0dc3 100644 --- a/app/v2/notifications/post_notifications.py +++ b/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