From 124115a62803f8e7df39fbf76ec3154a8ba36b4e Mon Sep 17 00:00:00 2001
From: Kyle MacMillan <16893311+k-macmillan@users.noreply.github.com>
Date: Fri, 7 Feb 2025 17:08:11 -0500
Subject: [PATCH] Added log prior to provider call for total time in system

---
 app/clients/sms/aws_pinpoint.py   | 8 ++++++++
 app/clients/sms/twilio.py         | 9 +++++++++
 app/delivery/send_to_providers.py | 7 +++++++
 3 files changed, 24 insertions(+)

diff --git a/app/clients/sms/aws_pinpoint.py b/app/clients/sms/aws_pinpoint.py
index c1d8cb422d..3cdade36be 100644
--- a/app/clients/sms/aws_pinpoint.py
+++ b/app/clients/sms/aws_pinpoint.py
@@ -19,6 +19,7 @@
     NOTIFICATION_TEMPORARY_FAILURE,
     NOTIFICATION_PERMANENT_FAILURE,
     PINPOINT_PROVIDER,
+    SMS_TYPE,
     STATUS_REASON_BLOCKED,
     STATUS_REASON_INVALID_NUMBER,
     STATUS_REASON_RETRYABLE,
@@ -83,6 +84,7 @@ def send_sms(
         reference,
         multi=True,
         sender=None,
+        created_at=datetime.utcnow(),
         **kwargs,
     ):
         aws_phone_number = self.origination_number if sender is None else sender
@@ -90,6 +92,12 @@ def send_sms(
 
         try:
             start_time = monotonic()
+            # Log how long it spent in our system before we sent it
+            self.logger.info(
+                'Total time spent to send %s notification: %s',
+                SMS_TYPE,
+                (datetime.utcnow() - created_at).total_seconds(),
+            )
             response = self._post_message_request(recipient_number, content, aws_phone_number)
 
         except (botocore.exceptions.ClientError, Exception) as e:
diff --git a/app/clients/sms/twilio.py b/app/clients/sms/twilio.py
index 7d1dc640ac..de6d97e2c6 100644
--- a/app/clients/sms/twilio.py
+++ b/app/clients/sms/twilio.py
@@ -19,6 +19,7 @@
     NOTIFICATION_SENDING,
     NOTIFICATION_SENT,
     NOTIFICATION_TEMPORARY_FAILURE,
+    SMS_TYPE,
     STATUS_REASON_BLOCKED,
     STATUS_REASON_INVALID_NUMBER,
     STATUS_REASON_RETRYABLE,
@@ -185,6 +186,7 @@ def send_sms(
         to,
         content,
         reference,
+        created_at=datetime.utcnow(),
         **kwargs,
     ) -> str:
         """
@@ -226,6 +228,13 @@ def send_sms(
 
                     self.logger.info('Twilio sender has sms_sender_specifics')
 
+            # Log how long it spent in our system before we sent it
+            self.logger.info(
+                'Total time spent to send %s notification: %s',
+                SMS_TYPE,
+                (datetime.utcnow() - created_at).total_seconds(),
+            )
+
             if messaging_service_sid is None:
                 # Make a request using a sender phone number.
                 message = self._client.messages.create(
diff --git a/app/delivery/send_to_providers.py b/app/delivery/send_to_providers.py
index bf2559d394..2896169f31 100644
--- a/app/delivery/send_to_providers.py
+++ b/app/delivery/send_to_providers.py
@@ -88,6 +88,7 @@ def send_sms_to_provider(
                 sender=notification.reply_to_text,
                 service_id=notification.service_id,
                 sms_sender_id=sms_sender_id,
+                created_at=notification.created_at,
             )
         except Exception as e:
             notification.billable_units = template.fragment_count
@@ -150,6 +151,12 @@ def send_email_to_provider(notification: Notification):
     else:
         email_reply_to = notification.reply_to_text
 
+        # Log how long it spent in our system before we sent it
+        current_app.logger.info(
+            'Total time spent to send %s notification: %s',
+            EMAIL_TYPE,
+            (datetime.utcnow() - notification.created_at).total_seconds(),
+        )
         reference = client.send_email(
             source=compute_source_email_address(service, client),
             to_addresses=validate_and_format_email_address(notification.to),