From 7a9c7561176f3a34d4cd4d7d263890457062d5d9 Mon Sep 17 00:00:00 2001 From: David McDonald Date: Mon, 27 Apr 2020 17:51:20 +0100 Subject: [PATCH] Add in lots of logging to our reporting tasks We've seen only some of these reporting tasks happen but with no log messages to indicate what happened and no app crashes. This hopefully will give us a better picture of a timeline. Note, I've tried to make our message format very consistent and good for searching for in kibana so I've changed that across this whole file for consistency. --- app/celery/reporting_tasks.py | 34 ++++++++++++++++++++++++++++------ 1 file changed, 28 insertions(+), 6 deletions(-) diff --git a/app/celery/reporting_tasks.py b/app/celery/reporting_tasks.py index 7ce1ff57a..9077747a1 100644 --- a/app/celery/reporting_tasks.py +++ b/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' )