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.
This commit is contained in:
David McDonald
2020-04-27 17:51:20 +01:00
parent 26793899d4
commit 7a9c756117

View File

@@ -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'
)