process_sms_client_response: accept & log delivery_iso_timestamp & receipt_iso_timestamp

app/celery/process_sms_client_response_tasks.py

@@ -27,7 +27,15 @@
 @notify_celery.task(
     bind=True, name="process-sms-client-response", max_retries=5, default_retry_delay=300, early_log_level=logging.DEBUG
 )
-def process_sms_client_response(self, status, provider_reference, client_name, detailed_status_code=None):
+def process_sms_client_response(
+    self,
+    status,
+    provider_reference,
+    client_name,
+    detailed_status_code=None,
+    delivery_iso_timestamp: str | None = None,
+    receipt_iso_timestamp: str | None = None,
+):
     # validate reference
     try:
         uuid.UUID(provider_reference, version=4)
@@ -50,12 +58,32 @@ def process_sms_client_response(self, status, provider_reference, client_name, d
     try:
         try:
             notification_status, detailed_status = response_parser(status, detailed_status_code)
+
+            delivery_dt = None
+            if delivery_iso_timestamp is not None:
+                try:
+                    delivery_dt = datetime.fromisoformat(delivery_iso_timestamp)
+                except ValueError:
+                    pass  # None it is, then
+
+            receipt_dt = None
+            if receipt_iso_timestamp is not None:
+                try:
+                    receipt_dt = datetime.fromisoformat(receipt_iso_timestamp)
+                except ValueError:
+                    pass  # None it is, then
+
+            uniform_now = datetime.utcnow()
             extra = {
                 "client_name": client_name,
                 "notification_status": notification_status,
                 "provider_status": status,
                 "detailed_status": detailed_status,
                 "detailed_status_code": detailed_status_code,
+                "receipt_received_at": receipt_dt,
+                "receipt_received_ago": (uniform_now - receipt_dt).total_seconds() if receipt_dt is not None else None,
+                "delivered_at": delivery_dt,
+                "delivered_ago": (uniform_now - delivery_dt).total_seconds() if delivery_dt is not None else None,
                 # for sms, we happen to use notification id as the "provider reference"
                 "notification_id": provider_reference,
             }

tests/app/celery/test_process_sms_client_response_tasks.py

@@ -34,6 +34,7 @@ def test_process_sms_response_raises_client_exception_for_unknown_status(
     assert sample_notification.status == NOTIFICATION_TECHNICAL_FAILURE
 
 
+@freeze_time("2020-10-20T03:06:07.3")
 @pytest.mark.parametrize(
     "status, detailed_status_code, sms_provider, expected_notification_status, reason",
     [
@@ -52,10 +53,23 @@ def test_process_sms_client_response_updates_notification_status(
     sample_notification.status = "sending"
 
     with caplog.at_level("INFO"):
-        process_sms_client_response(status, str(sample_notification.id), sms_provider, detailed_status_code)
+        process_sms_client_response(
+            status,
+            str(sample_notification.id),
+            sms_provider,
+            detailed_status_code,
+            "2020-10-20T03:04:05.1",
+            "2020-10-20T03:05:06.2",
+        )
 
     message = f"{sms_provider} callback returned status of {expected_notification_status}({status}): {reason}({detailed_status_code}) for reference: {sample_notification.id}"  # noqa
-    assert message in caplog.messages
+    record = next(r for r in caplog.records if "callback returned status of" in r.msg)
+    assert record.message == message
+    assert record.receipt_received_at == datetime(2020, 10, 20, 3, 5, 6, 200000)
+    assert record.receipt_received_ago == 61.1
+    assert record.delivered_at == datetime(2020, 10, 20, 3, 4, 5, 100000)
+    assert record.delivered_ago == 122.2
+
     assert sample_notification.status == expected_notification_status