Add logging around 3rd party delivery calls

- time SES, Twilio, fire text calls
- use monotonic for accuracy

app/clients/email/aws_ses.py

@@ -1,5 +1,6 @@
 import boto3
-
+from flask import current_app
+from monotonic import monotonic
 from app.clients.email import (EmailClientException, EmailClient)
 
 
@@ -34,6 +35,7 @@ class AwsSesClient(EmailClient):
             elif reply_to_addresses is None:
                 reply_to_addresses = []
 
+            start_time = monotonic()
             response = self._client.send_email(
                 Source=source,
                 Destination={
@@ -50,6 +52,8 @@ class AwsSesClient(EmailClient):
                             'Data': body}}
                 },
                 ReplyToAddresses=reply_to_addresses)
+            elapsed_time = monotonic() - start_time
+            current_app.logger.info("AWS SES request finished in {}".format(elapsed_time))
             return response['MessageId']
         except Exception as e:
             # TODO logging exceptions

app/clients/sms/firetext.py

@@ -1,8 +1,10 @@
 import logging
+from monotonic import monotonic
 from app.clients.sms import (
     SmsClient,
     SmsClientException
 )
+from flask import current_app
 from requests import request, RequestException, HTTPError
 
 logger = logging.getLogger(__name__)
@@ -36,6 +38,7 @@ class FiretextClient(SmsClient):
         }
 
         try:
+            start_time = monotonic()
             response = request(
                 "POST",
                 "https://www.firetext.co.uk/api/sendsms",
@@ -53,4 +56,7 @@ class FiretextClient(SmsClient):
                 )
             )
             raise api_error
+        finally:
+            elapsed_time = monotonic() - start_time
+            current_app.logger.info("Firetext request finished in {}".format(elapsed_time))
         return response

app/clients/sms/twilio.py

@@ -1,11 +1,9 @@
-import logging
+from monotonic import monotonic
 from app.clients.sms import (
     SmsClient, SmsClientException)
 from twilio.rest import TwilioRestClient
 from twilio import TwilioRestException
-
-
-logger = logging.getLogger(__name__)
+from flask import current_app
 
 
 class TwilioClientException(SmsClientException):
@@ -28,6 +26,7 @@ class TwilioClient(SmsClient):
         return self.name
 
     def send_sms(self, to, content):
+        start_time = monotonic()
         try:
             response = self.client.messages.create(
                 body=content,
@@ -36,8 +35,11 @@ class TwilioClient(SmsClient):
             )
             return response.sid
         except TwilioRestException as e:
-            logger.exception(e)
+            current_app.logger.exception(e)
             raise TwilioClientException(e)
+        finally:
+            elapsed_time = monotonic() - start_time
+            current_app.logger.info("Twilio request finished in {}".format(elapsed_time))
 
     def status(self, message_id):
         try:
@@ -46,5 +48,5 @@ class TwilioClient(SmsClient):
                 return response.status
             return None
         except TwilioRestException as e:
-            logger.exception(e)
+            current_app.logger.exception(e)
             raise TwilioClientException(e)

requirements.txt

@@ -15,6 +15,7 @@ boto3==1.2.3
 boto==2.39.0
 celery==3.1.20
 twilio==4.6.0
+monotonic==0.3
 
 
 git+https://github.com/alphagov/notifications-python-client.git@0.2.6#egg=notifications-python-client==0.2.6