Merge pull request #2822 from alphagov/extra-logging-reporting-tasks

Add in lots of logging to our reporting tasks

app/celery/reporting_tasks.py

@@ -23,6 +23,7 @@ from app.models import (
 @cronitor("create-nightly-billing")
 @statsd(namespace="tasks")
 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:
@@ -31,30 +32,39 @@ def create_nightly_billing(day_start=None):
         # When calling the task its a string in the format of "YYYY-MM-DD"
         day_start = datetime.strptime(day_start, "%Y-%m-%d").date()
     for i in range(0, 4):
-        process_day = day_start - timedelta(days=i)
+        process_day = (day_start - timedelta(days=i)).isoformat()
 
         create_nightly_billing_for_day.apply_async(
-            kwargs={'process_day': process_day.isoformat()},
+            kwargs={'process_day': process_day},
             queue=QueueNames.REPORTING
         )
+        current_app.logger.info(
+            f"create-nightly-billing task: create-nightly-billing-for-day task created for {process_day}"
+        )
 
 
 @notify_celery.task(name="create-nightly-billing-for-day")
 @statsd(namespace="tasks")
 def create_nightly_billing_for_day(process_day):
     process_day = datetime.strptime(process_day, "%Y-%m-%d").date()
+    current_app.logger.info(
+        f'create-nightly-billing-for-day task for {process_day}: started'
+    )
 
     start = datetime.utcnow()
     transit_data = fetch_billing_data_for_day(process_day=process_day)
     end = datetime.utcnow()
 
-    current_app.logger.info(f'create-nightly-billing-for-day {process_day} fetched in {(end - start).seconds} seconds')
+    current_app.logger.info(
+        f'create-nightly-billing-for-day task for {process_day}: data fetched in {(end - start).seconds} seconds'
+    )
 
     for data in transit_data:
         update_fact_billing(data, process_day)
 
     current_app.logger.info(
-        f"create-nightly-billing-for-day task complete. {len(transit_data)} rows updated for day: {process_day}"
+        f"create-nightly-billing-for-day task for {process_day}: "
+        f"task complete. {len(transit_data)} rows updated"
     )
 
 
@@ -62,6 +72,7 @@ def create_nightly_billing_for_day(process_day):
 @cronitor("create-nightly-notification-status")
 @statsd(namespace="tasks")
 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
@@ -72,6 +83,10 @@ def create_nightly_notification_status():
                 kwargs={'process_day': process_day.isoformat(), 'notification_type': notification_type},
                 queue=QueueNames.REPORTING
             )
+            current_app.logger.info(
+                f"create-nightly-notification-status task: create-nightly-notification-status-for-day task created "
+                f"for type {notification_type} for {process_day}"
+            )
     # letters get modified for a longer time period than sms and email, so we need to reprocess for more days
     for i in range(10):
         process_day = yesterday - timedelta(days=i)
@@ -79,24 +94,31 @@ def create_nightly_notification_status():
             kwargs={'process_day': process_day.isoformat(), 'notification_type': LETTER_TYPE},
             queue=QueueNames.REPORTING
         )
+        current_app.logger.info(
+            f"create-nightly-notification-status task: create-nightly-notification-status-for-day task created "
+            f"for type letter for {process_day}"
+        )
 
 
 @notify_celery.task(name="create-nightly-notification-status-for-day")
 @statsd(namespace="tasks")
 def create_nightly_notification_status_for_day(process_day, notification_type):
     process_day = datetime.strptime(process_day, "%Y-%m-%d").date()
+    current_app.logger.info(
+        f'create-nightly-notification-status-for-day task for {process_day} type {notification_type}: started'
+    )
 
     start = datetime.utcnow()
     transit_data = fetch_notification_status_for_day(process_day=process_day, notification_type=notification_type)
     end = datetime.utcnow()
     current_app.logger.info(
-        f'create-nightly-notification-status-for-day {process_day} type {notification_type} task: '
+        f'create-nightly-notification-status-for-day task for {process_day} type {notification_type}: '
         f'data fetched in {(end - start).seconds} seconds'
     )
 
     update_fact_notification_status(transit_data, process_day, notification_type)
 
     current_app.logger.info(
-        f'create-nightly-notification-status-for-day {process_day} type {notification_type} task: '
+        f'create-nightly-notification-status-for-day task for {process_day} type {notification_type}: '
         f'task complete - {len(transit_data)} rows updated'
     )