merge from main

app/celery/tasks.py

@@ -24,7 +24,8 @@ from app.notifications.process_notifications import persist_notification
 from app.notifications.validators import check_service_over_total_message_limit
 from app.serialised_models import SerialisedService, SerialisedTemplate
 from app.service.utils import service_allowed_to_send_to
-from app.utils import DATETIME_FORMAT, utc_now
+from app.utils import DATETIME_FORMAT, hilite, scrub, utc_now
+from app.errors import TotalRequestsError
 from notifications_utils.recipients import RecipientCSV
 
 
@@ -189,6 +190,7 @@ def save_sms(self, service_id, notification_id, encrypted_notification, sender_i
     # Return False when trial mode services try sending notifications
     # to non-team and non-simulated recipients.
     if not service_allowed_to_send_to(notification["to"], service, KeyType.NORMAL):
+        current_app.logger.info(hilite(scrub(f"service not allowed to send to {notification['to']}, aborting")))
         current_app.logger.debug(
             "SMS {} failed as restricted service".format(notification_id)
         )
@@ -219,6 +221,7 @@ def save_sms(self, service_id, notification_id, encrypted_notification, sender_i
         )
 
         # Kick off sns process in provider_tasks.py
+        current_app.logger.info(hilite(scrub(f"Going to deliver sms for recipient: {notification['to']}")))
         provider_tasks.deliver_sms.apply_async(
             [str(saved_notification.id)], queue=QueueNames.SEND_SMS
         )

app/clients/cloudwatch/aws_cloudwatch.py

@@ -9,7 +9,7 @@ from flask import current_app
 from app.clients import AWS_CLIENT_CONFIG, Client
 from app.cloudfoundry_config import cloud_config
 from app.exceptions import NotificationTechnicalFailureException
-from app.utils import utc_now
+from app.utils import hilite, scrub, utc_now
 
 
 class AwsCloudwatchClient(Client):
@@ -124,6 +124,7 @@ class AwsCloudwatchClient(Client):
             self.warn_if_dev_is_opted_out(
                 message["delivery"]["providerResponse"], notification_id
             )
+            current_app.logger.info(hilite(scrub(f"DELIVERED: {message}")))
             return (
                 "success",
                 message["delivery"]["providerResponse"],
@@ -140,6 +141,8 @@ class AwsCloudwatchClient(Client):
             self.warn_if_dev_is_opted_out(
                 message["delivery"]["providerResponse"], notification_id
             )
+
+            current_app.logger.info(hilite(scrub(f"FAILED: {message}")))
             return (
                 "failure",
                 message["delivery"]["providerResponse"],

app/delivery/send_to_providers.py

@@ -13,7 +13,7 @@ from app.dao.provider_details_dao import get_provider_details_by_notification_ty
 from app.enums import BrandType, KeyType, NotificationStatus, NotificationType
 from app.exceptions import NotificationTechnicalFailureException
 from app.serialised_models import SerialisedService, SerialisedTemplate
-from app.utils import utc_now
+from app.utils import hilite, scrub, utc_now
 from notifications_utils.template import (
     HTMLEmailTemplate,
     PlainTextEmailTemplate,
@@ -109,15 +109,19 @@ def send_sms_to_provider(notification):
                     "international": notification.international,
                 }
                 db.session.close()  # no commit needed as no changes to objects have been made above
-                current_app.logger.info("sending to sms")
+
                 message_id = provider.send_sms(**send_sms_kwargs)
                 current_app.logger.info(f"got message_id {message_id}")
             except Exception as e:
-                current_app.logger.error(e)
+                msg = f"FAILED sending message for this recipient: {recipient} to sms"
+                current_app.logger.error(hilite(scrub(f"{msg} {e}")))
+
                 notification.billable_units = template.fragment_count
                 dao_update_notification(notification)
                 raise e
             else:
+                msg = f"Sending message for this recipient: {recipient} to sms"
+                current_app.logger.info(hilite(scrub(msg)))
                 notification.billable_units = template.fragment_count
                 update_notification_to_sending(notification, provider)
     return message_id

app/notifications/process_notifications.py

@@ -12,7 +12,8 @@ from app.dao.notifications_dao import (
 from app.enums import KeyType, NotificationStatus, NotificationType
 from app.errors import BadRequestError
 from app.models import Notification
-from app.utils import utc_now
+from app.utils import hilite, scrub, utc_now
+from app.errors import BadRequestError
 from notifications_utils.recipients import (
     format_email_address,
     get_international_phone_info,
@@ -110,6 +111,7 @@ def persist_notification(
         formatted_recipient = validate_and_format_phone_number(
             recipient, international=True
         )
+        current_app.logger.info(hilite(scrub(f"Persisting notification with recipient {formatted_recipient}")))
         recipient_info = get_international_phone_info(formatted_recipient)
         notification.normalised_to = formatted_recipient
         notification.international = recipient_info.international

app/service/rest.py

@@ -473,11 +473,6 @@ def get_all_notifications_for_service(service_id):
         )
     current_app.logger.debug(f"number of notifications are {len(notifications)}")
 
-    if len(notifications) > 0:
-        current_app.logger.debug(f"first notification is {notifications[0]}")
-    else:
-        current_app.logger.debug("there are no notifications to show")
-
     # We try and get the next page of results to work out if we need provide a pagination link to the next page
     # in our response if it exists. Note, this could be done instead by changing `count_pages` in the previous
     # call to be True which will enable us to use Flask-Sqlalchemy to tell if there is a next page of results but

app/utils.py

@@ -1,3 +1,4 @@
+import re
 from datetime import datetime, timedelta, timezone
 
 from flask import url_for
@@ -144,3 +145,15 @@ def naive_utcnow():
 
 def utc_now():
     return naive_utcnow()
+
+
+def scrub(msg):
+    # Eventually we want to scrub all messages in all logs for phone numbers
+    # and email addresses, masking them.  Ultimately this will probably get
+    # refactored into a 'SafeLogger' subclass or something, but let's start here
+    # with phones.
+    phones = re.findall("(?:\\+ *)?\\d[\\d\\- ]{7,}\\d", msg)
+    phones = [phone.replace("-", "").replace(" ", "") for phone in phones]
+    for phone in phones:
+        msg = msg.replace(phone, f"1XXXXX{phone[-5:]}")
+    return msg