#2159 - Update Total Time For Twilio Delivery Status (#2168)

app/celery/common.py

@@ -102,10 +102,19 @@ 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 (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,
-            (end_time - start_time).total_seconds(),
+            corrected_total_time,
             status,
             provider,
         )

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