From f8a401ff863711a38131ca3db0a99e933259c5df Mon Sep 17 00:00:00 2001 From: Kyle MacMillan Date: Fri, 6 Dec 2024 10:23:34 -0500 Subject: [PATCH 1/3] Updated total time and commented --- app/celery/common.py | 7 ++++++- 1 file changed, 6 insertions(+), 1 deletion(-) diff --git a/app/celery/common.py b/app/celery/common.py index 8e6a5f5670..6e2a07bf7c 100644 --- a/app/celery/common.py +++ b/app/celery/common.py @@ -102,10 +102,15 @@ def log_notification_total_time( """Logs how long it took a notification to go from created to delivered""" if status == NOTIFICATION_DELIVERED: end_time = event_timestamp or datetime.now(timezone.utc).replace(tzinfo=None) + total_time = (end_time - start_time).total_seconds() + + # Twilio RawDlrDoneDate can make this negative + # https://www.twilio.com/en-us/changelog/addition-of-rawdlrdonedate-to-delivered-and-undelivered-status-webhooks + corrected_total_time = total_time if total_time > 0.0 else 0.0 current_app.logger.info( 'notification %s took %ss total time to reach %s status - %s', notification_id, - (end_time - start_time).total_seconds(), + corrected_total_time, status, provider, ) From 779f96d8fe78921424104e65ab463f051279ec7e Mon Sep 17 00:00:00 2001 From: Kyle MacMillan Date: Fri, 6 Dec 2024 10:34:25 -0500 Subject: [PATCH 2/3] Updated to be more accurate for the total time it took --- app/celery/common.py | 6 +++++- 1 file changed, 5 insertions(+), 1 deletion(-) diff --git a/app/celery/common.py b/app/celery/common.py index 6e2a07bf7c..7ff228d4c0 100644 --- a/app/celery/common.py +++ b/app/celery/common.py @@ -106,7 +106,11 @@ def log_notification_total_time( # Twilio RawDlrDoneDate can make this negative # https://www.twilio.com/en-us/changelog/addition-of-rawdlrdonedate-to-delivered-and-undelivered-status-webhooks - corrected_total_time = total_time if total_time > 0.0 else 0.0 + corrected_total_time = ( + total_time + if total_time > 0.0 + else (datetime.now(timezone.utc).replace(tzinfo=None) - start_time).total_seconds() + ) current_app.logger.info( 'notification %s took %ss total time to reach %s status - %s', notification_id, From ee302b5f89f032003cfbad926e4782d2b5a162e0 Mon Sep 17 00:00:00 2001 From: Kyle MacMillan Date: Fri, 6 Dec 2024 10:58:00 -0500 Subject: [PATCH 3/3] Made test for negative time values --- tests/app/celery/test_common.py | 30 ++++++++++++++++++++++++++---- 1 file changed, 26 insertions(+), 4 deletions(-) diff --git a/tests/app/celery/test_common.py b/tests/app/celery/test_common.py index 8227a5dfb0..435777523f 100644 --- a/tests/app/celery/test_common.py +++ b/tests/app/celery/test_common.py @@ -1,4 +1,4 @@ -import datetime +from datetime import datetime, timedelta, timezone from uuid import uuid4 from freezegun import freeze_time @@ -11,6 +11,7 @@ NOTIFICATION_PENDING, NOTIFICATION_SENDING, NOTIFICATION_SENT, + TWILIO_PROVIDER, ) @@ -23,7 +24,7 @@ def test_ut_log_notification_total_time( mock_logger = mocker.patch('app.celery.common.current_app.logger.info') notification_id = uuid4() with freeze_time('2024-04-04 17:16:43'): - created_at = datetime.datetime.fromisoformat('2024-04-04 17:16:41') + created_at = datetime.fromisoformat('2024-04-04 17:16:41') log_notification_total_time( notification_id=notification_id, @@ -35,7 +36,7 @@ def test_ut_log_notification_total_time( mock_logger.assert_called_once_with( 'notification %s took %ss total time to reach %s status - %s', notification_id, - (datetime.datetime.now() - created_at).total_seconds(), + (datetime.now() - created_at).total_seconds(), NOTIFICATION_DELIVERED, provider, ) @@ -60,9 +61,30 @@ def test_ut_skip_log_notification_total_time( mock_logger = mocker.patch('app.celery.common.current_app.logger.info') log_notification_total_time( notification_id=uuid4(), - start_time=datetime.datetime.now(), + start_time=datetime.now(), status=status, provider=provider, ) mock_logger.assert_not_called() + + +def test_log_total_time_negative_value( + mocker, + client, +): + mock_logger = mocker.patch('app.celery.common.current_app.logger.info') + start_time = datetime.now(timezone.utc).replace(tzinfo=None) - timedelta(seconds=1) + event_timestamp = datetime.now(timezone.utc).replace(tzinfo=None) - timedelta(seconds=3) + + notification_id = str(uuid4()) + log_notification_total_time( + notification_id, + start_time, + NOTIFICATION_DELIVERED, + TWILIO_PROVIDER, + event_timestamp, + ) + + # Test that the total time logged is > 0 + assert float(mock_logger.call_args[0][2]) > 0