From 920d2c4539c5701693c3202e91a8c742fbb5d3f7 Mon Sep 17 00:00:00 2001 From: Kenneth Kehl <@kkehl@flexion.us> Date: Wed, 5 Jun 2024 12:42:35 -0700 Subject: [PATCH] debug for notify-admin-1588 --- app/celery/tasks.py | 4 +++- app/clients/cloudwatch/aws_cloudwatch.py | 5 ++++- app/delivery/send_to_providers.py | 10 +++++++--- app/notifications/process_notifications.py | 3 ++- app/service/rest.py | 5 ----- app/utils.py | 13 +++++++++++++ poetry.lock | 8 ++------ tests/app/test_utils.py | 8 ++++++++ 8 files changed, 39 insertions(+), 17 deletions(-) diff --git a/app/celery/tasks.py b/app/celery/tasks.py index e0428152a..1950712af 100644 --- a/app/celery/tasks.py +++ b/app/celery/tasks.py @@ -23,7 +23,7 @@ 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.v2.errors import TotalRequestsError from notifications_utils.recipients import RecipientCSV @@ -189,6 +189,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 +220,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 ) diff --git a/app/clients/cloudwatch/aws_cloudwatch.py b/app/clients/cloudwatch/aws_cloudwatch.py index d010957ac..14d8513c5 100644 --- a/app/clients/cloudwatch/aws_cloudwatch.py +++ b/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"], diff --git a/app/delivery/send_to_providers.py b/app/delivery/send_to_providers.py index a9b90d368..a347b89ad 100644 --- a/app/delivery/send_to_providers.py +++ b/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 diff --git a/app/notifications/process_notifications.py b/app/notifications/process_notifications.py index 2a423767d..d899a8146 100644 --- a/app/notifications/process_notifications.py +++ b/app/notifications/process_notifications.py @@ -11,7 +11,7 @@ from app.dao.notifications_dao import ( ) from app.enums import KeyType, NotificationStatus, NotificationType from app.models import Notification -from app.utils import utc_now +from app.utils import hilite, scrub, utc_now from app.v2.errors import BadRequestError from notifications_utils.recipients import ( format_email_address, @@ -110,6 +110,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 diff --git a/app/service/rest.py b/app/service/rest.py index be8d55f45..0503c71d5 100644 --- a/app/service/rest.py +++ b/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 diff --git a/app/utils.py b/app/utils.py index e286d6539..b23a000d1 100644 --- a/app/utils.py +++ b/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 diff --git a/poetry.lock b/poetry.lock index a9d3c4056..a7f4120df 100644 --- a/poetry.lock +++ b/poetry.lock @@ -1,4 +1,4 @@ -# This file is automatically @generated by Poetry 1.8.2 and should not be changed by hand. +# This file is automatically @generated by Poetry 1.8.3 and should not be changed by hand. [[package]] name = "aiohttp" @@ -2098,13 +2098,9 @@ files = [ {file = "lxml-5.2.2-cp36-cp36m-win_amd64.whl", hash = "sha256:edcfa83e03370032a489430215c1e7783128808fd3e2e0a3225deee278585196"}, {file = "lxml-5.2.2-cp37-cp37m-macosx_10_9_x86_64.whl", hash = "sha256:28bf95177400066596cdbcfc933312493799382879da504633d16cf60bba735b"}, {file = "lxml-5.2.2-cp37-cp37m-manylinux_2_12_i686.manylinux2010_i686.manylinux_2_17_i686.manylinux2014_i686.whl", hash = "sha256:3a745cc98d504d5bd2c19b10c79c61c7c3df9222629f1b6210c0368177589fb8"}, - {file = "lxml-5.2.2-cp37-cp37m-manylinux_2_17_aarch64.manylinux2014_aarch64.whl", hash = "sha256:1b590b39ef90c6b22ec0be925b211298e810b4856909c8ca60d27ffbca6c12e6"}, {file = "lxml-5.2.2-cp37-cp37m-manylinux_2_17_x86_64.manylinux2014_x86_64.whl", hash = "sha256:b336b0416828022bfd5a2e3083e7f5ba54b96242159f83c7e3eebaec752f1716"}, - {file = "lxml-5.2.2-cp37-cp37m-manylinux_2_28_aarch64.whl", hash = "sha256:c2faf60c583af0d135e853c86ac2735ce178f0e338a3c7f9ae8f622fd2eb788c"}, {file = "lxml-5.2.2-cp37-cp37m-manylinux_2_28_x86_64.whl", hash = "sha256:4bc6cb140a7a0ad1f7bc37e018d0ed690b7b6520ade518285dc3171f7a117905"}, - {file = "lxml-5.2.2-cp37-cp37m-musllinux_1_1_aarch64.whl", hash = "sha256:7ff762670cada8e05b32bf1e4dc50b140790909caa8303cfddc4d702b71ea184"}, {file = "lxml-5.2.2-cp37-cp37m-musllinux_1_1_x86_64.whl", hash = "sha256:57f0a0bbc9868e10ebe874e9f129d2917750adf008fe7b9c1598c0fbbfdde6a6"}, - {file = "lxml-5.2.2-cp37-cp37m-musllinux_1_2_aarch64.whl", hash = "sha256:a6d2092797b388342c1bc932077ad232f914351932353e2e8706851c870bca1f"}, {file = "lxml-5.2.2-cp37-cp37m-musllinux_1_2_x86_64.whl", hash = "sha256:60499fe961b21264e17a471ec296dcbf4365fbea611bf9e303ab69db7159ce61"}, {file = "lxml-5.2.2-cp37-cp37m-win32.whl", hash = "sha256:d9b342c76003c6b9336a80efcc766748a333573abf9350f4094ee46b006ec18f"}, {file = "lxml-5.2.2-cp37-cp37m-win_amd64.whl", hash = "sha256:b16db2770517b8799c79aa80f4053cd6f8b716f21f8aca962725a9565ce3ee40"}, @@ -2493,6 +2489,7 @@ files = [ {file = "msgpack-1.0.8-cp39-cp39-musllinux_1_1_x86_64.whl", hash = "sha256:5fbb160554e319f7b22ecf530a80a3ff496d38e8e07ae763b9e82fadfe96f273"}, {file = "msgpack-1.0.8-cp39-cp39-win32.whl", hash = "sha256:f9af38a89b6a5c04b7d18c492c8ccf2aee7048aff1ce8437c4683bb5a1df893d"}, {file = "msgpack-1.0.8-cp39-cp39-win_amd64.whl", hash = "sha256:ed59dd52075f8fc91da6053b12e8c89e37aa043f8986efd89e61fae69dc1b011"}, + {file = "msgpack-1.0.8-py3-none-any.whl", hash = "sha256:24f727df1e20b9876fa6e95f840a2a2651e34c0ad147676356f4bf5fbb0206ca"}, {file = "msgpack-1.0.8.tar.gz", hash = "sha256:95c02b0e27e706e48d0e5426d1710ca78e0f0628d6e89d5b5a5b91a5f12274f3"}, ] @@ -3475,7 +3472,6 @@ files = [ {file = "PyYAML-6.0.1-cp311-cp311-win_amd64.whl", hash = "sha256:bf07ee2fef7014951eeb99f56f39c9bb4af143d8aa3c21b1677805985307da34"}, {file = "PyYAML-6.0.1-cp312-cp312-macosx_10_9_x86_64.whl", hash = "sha256:855fb52b0dc35af121542a76b9a84f8d1cd886ea97c84703eaa6d88e37a2ad28"}, {file = "PyYAML-6.0.1-cp312-cp312-macosx_11_0_arm64.whl", hash = "sha256:40df9b996c2b73138957fe23a16a4f0ba614f4c0efce1e9406a184b6d07fa3a9"}, - {file = "PyYAML-6.0.1-cp312-cp312-manylinux_2_17_aarch64.manylinux2014_aarch64.whl", hash = "sha256:a08c6f0fe150303c1c6b71ebcd7213c2858041a7e01975da3a99aed1e7a378ef"}, {file = "PyYAML-6.0.1-cp312-cp312-manylinux_2_17_x86_64.manylinux2014_x86_64.whl", hash = "sha256:6c22bec3fbe2524cde73d7ada88f6566758a8f7227bfbf93a408a9d86bcc12a0"}, {file = "PyYAML-6.0.1-cp312-cp312-musllinux_1_1_x86_64.whl", hash = "sha256:8d4e9c88387b0f5c7d5f281e55304de64cf7f9c0021a3525bd3b1c542da3b0e4"}, {file = "PyYAML-6.0.1-cp312-cp312-win32.whl", hash = "sha256:d483d2cdf104e7c9fa60c544d92981f12ad66a457afae824d146093b8c294c54"}, diff --git a/tests/app/test_utils.py b/tests/app/test_utils.py index b39d3a2c0..bbe37256a 100644 --- a/tests/app/test_utils.py +++ b/tests/app/test_utils.py @@ -13,6 +13,7 @@ from app.utils import ( get_reference_from_personalisation, get_uuid_string_or_none, midnight_n_days_ago, + scrub, ) @@ -94,6 +95,13 @@ def test_get_public_notify_type_text(): ) +def test_scrub(): + result = scrub( + "This is a message with 17775554324, and also 18884449323 and also 17775554324" + ) + assert result == "This is a message with 1XXXXX54324, and also 1XXXXX49323 and also 1XXXXX54324" + + # This method is used for simulating bulk sends. We use localstack and run on a developer's machine to do the # simulation. Please see docs->bulk_testing.md for instructions. # def test_generate_csv_for_bulk_testing():