Merge pull request #3374 from alphagov/log-periodic-180330449

Log activity on all periodic Celery tasks

app/celery/letters_pdf_tasks.py

@@ -126,7 +126,6 @@ def collate_letter_pdfs_to_be_sent():
     that have not yet been sent.
     If run after midnight, it will collect up letters created before 5:30pm the day before.
     """
-    current_app.logger.info("starting collate-letter-pdfs-to-be-sent")
     print_run_date = convert_utc_to_bst(datetime.utcnow())
     if print_run_date.time() < LETTER_PROCESSING_DEADLINE:
         print_run_date = print_run_date - timedelta(days=1)

app/celery/reporting_tasks.py

@@ -20,7 +20,6 @@ from app.models import EMAIL_TYPE, LETTER_TYPE, SMS_TYPE
 @notify_celery.task(name="create-nightly-billing")
 @cronitor("create-nightly-billing")
 def create_nightly_billing(day_start=None):
-    current_app.logger.info("create-nightly-billing task: started")
     # day_start is a datetime.date() object. e.g.
     # up to 4 days of data counting back from day_start is consolidated
     if day_start is None:
@@ -67,7 +66,6 @@ def create_nightly_billing_for_day(process_day):
 @notify_celery.task(name="create-nightly-notification-status")
 @cronitor("create-nightly-notification-status")
 def create_nightly_notification_status():
-    current_app.logger.info("create-nightly-notification-status task: started")
     yesterday = convert_utc_to_bst(datetime.utcnow()).date() - timedelta(days=1)
 
     # email and sms

app/cronitor.py

@@ -5,12 +5,15 @@ from flask import current_app
 
 
 def cronitor(task_name):
-    # check if task_name is in config
     def decorator(func):
         def ping_cronitor(command):
             if not current_app.config['CRONITOR_ENABLED']:
                 return
 
+            # it's useful to have a log that a periodic task has started in case it
+            # get stuck without generating any other logs - we know it got this far
+            current_app.logger.info(f'Pinging Cronitor for Celery task {task_name}')
+
             task_slug = current_app.config['CRONITOR_KEYS'].get(task_name)
             if not task_slug:
                 current_app.logger.error(

tests/app/test_cronitor.py

@@ -1,3 +1,4 @@
+import logging
 from urllib import parse
 
 import pytest
@@ -75,6 +76,9 @@ def test_cronitor_does_nothing_if_cronitor_not_enabled(notify_api, rmock):
 
 
 def test_cronitor_does_nothing_if_name_not_recognised(notify_api, rmock, caplog):
+    # ignore "INFO" log about task starting
+    caplog.set_level(logging.ERROR)
+
     with set_config_values(notify_api, {
         'CRONITOR_ENABLED': True,
         'CRONITOR_KEYS': {'not-hello': 'other'}