Added log prior to provider call for total time in system

department-of-veterans-affairs · Feb 7, 2025 · 124115a · 124115a
1 parent 69912b9
commit 124115a
Show file tree

Hide file tree

Showing 3 changed files with 24 additions and 0 deletions.
diff --git 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,13 +84,20 @@ 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
         recipient_number = str(to)
 
         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
@@ -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
@@ -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),