Move some verbose celery INFO-level logs to reduce log size (#2019)

* Remove celery task time execution log

* Moved celery task time execution log to DEBUG, sending as statsd metrics

* Moved info level log into debug

* Formatting

* Removed types; moved some more info log into debug

* Fixed errors + more info logs into debug

app/celery/celery.py

@@ -12,13 +12,19 @@ def worker_process_shutdown(sender, signal, pid, exitcode, **kwargs):
 
 
 def make_task(app):
+    from app import statsd_client
+
     class NotifyTask(Task):
         abstract = True
         start = None
 
         def on_success(self, retval, task_id, args, kwargs):
-            elapsed_time = time.time() - self.start
-            app.logger.info("{task_name} took {time}".format(task_name=self.name, time="{0:.4f}".format(elapsed_time)))
+            task_name = self.name
+            now = time.time()
+            statsd_client.timing_with_dates(f"celery-task.{task_name}.total-time", now, self.start)
+
+            elapsed_time = now - self.start
+            app.logger.debug("{task_name} took {time}".format(task_name=task_name, time="{0:.4f}".format(elapsed_time)))
 
         def on_failure(self, exc, task_id, args, kwargs, einfo):
             # ensure task will log exceptions to correct handlers

app/celery/provider_tasks.py

@@ -63,7 +63,7 @@ def deliver_sms(self, notification_id):
 @statsd(namespace="tasks")
 def deliver_email(self, notification_id):
     try:
-        current_app.logger.info("Start sending email for notification id: {}".format(notification_id))
+        current_app.logger.debug("Start sending email for notification id: {}".format(notification_id))
         notification = notifications_dao.get_notification_by_id(notification_id)
         if not notification:
             raise NoResultFound()

app/celery/tasks.py

@@ -277,12 +277,12 @@ def save_smss(self, service_id: Optional[str], signed_notifications: List[Signed
     try:
         # If the data is not present in the encrypted data then fallback on whats needed for process_job.
         saved_notifications = persist_notifications(verified_notifications)
-        current_app.logger.info(
+        current_app.logger.debug(
             f"Saved following notifications into db: {notification_id_queue.keys()} associated with receipt {receipt}"
         )
         if receipt:
             acknowledge_receipt(SMS_TYPE, process_type, receipt)
-            current_app.logger.info(
+            current_app.logger.debug(
                 f"Batch saving: receipt_id {receipt} removed from buffer queue for notification_id {notification_id} for process_type {process_type}"
             )
         else:
@@ -297,7 +297,7 @@ def save_smss(self, service_id: Optional[str], signed_notifications: List[Signed
         signed_and_verified = list(zip(signed_notifications, verified_notifications))
         handle_batch_error_and_forward(self, signed_and_verified, SMS_TYPE, e, receipt, template)
 
-    current_app.logger.info(f"Sending following sms notifications to AWS: {notification_id_queue.keys()}")
+    current_app.logger.debug(f"Sending following sms notifications to AWS: {notification_id_queue.keys()}")
     for notification_obj in saved_notifications:
         try:
             if not current_app.config["FF_EMAIL_DAILY_LIMIT"]:
@@ -383,7 +383,7 @@ def save_emails(self, _service_id: Optional[str], signed_notifications: List[Sig
     try:
         # If the data is not present in the encrypted data then fallback on whats needed for process_job
         saved_notifications = persist_notifications(verified_notifications)
-        current_app.logger.info(
+        current_app.logger.debug(
             f"Saved following notifications into db: {notification_id_queue.keys()} associated with receipt {receipt}"
         )
         if receipt:
@@ -392,7 +392,7 @@ def save_emails(self, _service_id: Optional[str], signed_notifications: List[Sig
             # at this point in the code we have a list of notifications (saved_notifications)
             # which could use multiple templates
             acknowledge_receipt(EMAIL_TYPE, process_type, receipt)
-            current_app.logger.info(
+            current_app.logger.debug(
                 f"Batch saving: receipt_id {receipt} removed from buffer queue for notification_id {notification_id} for process_type {process_type}"
             )
         else:
@@ -415,7 +415,7 @@ def try_to_send_notifications_to_queue(notification_id_queue, service, saved_not
     Loop through saved_notifications, check if the service has hit their daily rate limit,
     and if not, call send_notification_to_queue on notification
     """
-    current_app.logger.info(f"Sending following email notifications to AWS: {notification_id_queue.keys()}")
+    current_app.logger.debug(f"Sending following email notifications to AWS: {notification_id_queue.keys()}")
     # todo: fix this potential bug
     # service is whatever it was set to last in the for loop above.
     # at this point in the code we have a list of notifications (saved_notifications)