Merge pull request #1602 from GSA/main

ccostino · web-flow · commit 385b342bf28e · 2025-03-14T17:43:02.000-04:00
03/14/2025 Production Deploy
diff --git a/.github/dependabot.yml b/.github/dependabot.yml
@@ -9,3 +9,5 @@ updates:
     directory: "/" # Location of package manifests
     schedule:
       interval: "daily"
+    labels:
+      - "dependabot" # Custom label to identify Dependabot PRs
diff --git a/app/aws/s3.py b/app/aws/s3.py
@@ -118,7 +118,7 @@ def list_s3_objects():
                 break
     except Exception:
         current_app.logger.exception(
-            "An error occurred while regenerating cache #notify-admin-1200",
+            "An error occurred while regenerating cache #notify-debug-admin-1200",
         )
 
 
@@ -200,7 +200,7 @@ def read_s3_file(bucket_name, object_key, s3res):
 
     except LookupError:
         # perhaps our key is not formatted as we expected.  If so skip it.
-        current_app.logger.exception("LookupError #notify-admin-1200")
+        current_app.logger.exception("LookupError #notify-debug-admin-1200")
 
 
 def get_s3_files():
@@ -213,7 +213,7 @@ def get_s3_files():
 
     s3res = get_s3_resource()
     current_app.logger.info(
-        f"job_cache length before regen: {len_job_cache()} #notify-admin-1200"
+        f"job_cache length before regen: {len_job_cache()} #notify-debug-admin-1200"
     )
     try:
         with ThreadPoolExecutor() as executor:
@@ -222,7 +222,7 @@ def get_s3_files():
         current_app.logger.exception("Connection pool issue")
 
     current_app.logger.info(
-        f"job_cache length after regen: {len_job_cache()} #notify-admin-1200"
+        f"job_cache length after regen: {len_job_cache()} #notify-debug-admin-1200"
     )
 
 
@@ -290,7 +290,7 @@ def file_exists(file_location):
 
 def get_job_location(service_id, job_id):
     current_app.logger.debug(
-        f"#s3-partitioning NEW JOB_LOCATION: {NEW_FILE_LOCATION_STRUCTURE.format(service_id, job_id)}"
+        f"#notify-debug-s3-partitioning NEW JOB_LOCATION: {NEW_FILE_LOCATION_STRUCTURE.format(service_id, job_id)}"
     )
     return (
         current_app.config["CSV_UPLOAD_BUCKET"]["bucket"],
@@ -308,7 +308,7 @@ def get_old_job_location(service_id, job_id):
     Remove this when everything works with the NEW_FILE_LOCATION_STRUCTURE.
     """
     current_app.logger.debug(
-        f"#s3-partitioning OLD JOB LOCATION: {FILE_LOCATION_STRUCTURE.format(service_id, job_id)}"
+        f"#notify-debug-s3-partitioning OLD JOB LOCATION: {FILE_LOCATION_STRUCTURE.format(service_id, job_id)}"
     )
     return (
         current_app.config["CSV_UPLOAD_BUCKET"]["bucket"],
@@ -507,7 +507,7 @@ def get_personalisation_from_s3(service_id, job_id, job_row_number):
 
 def get_job_metadata_from_s3(service_id, job_id):
     current_app.logger.debug(
-        f"#s3-partitioning CALLING GET_JOB_METADATA with {service_id}, {job_id}"
+        f"#notify-debug-s3-partitioning CALLING GET_JOB_METADATA with {service_id}, {job_id}"
     )
     obj = get_s3_object(*get_job_location(service_id, job_id))
     return obj.get()["Metadata"]
diff --git a/app/celery/scheduled_tasks.py b/app/celery/scheduled_tasks.py
@@ -325,7 +325,14 @@ def batch_insert_notifications(self):
             elif isinstance(notification_dict["created_at"], list):
                 notification_dict["created_at"] = notification_dict["created_at"][0]
             notification = Notification(**notification_dict)
-            if notification is not None:
+            # notify-api-749 do not write to db
+            # if we have a verify_code we know this is the authentication notification at login time
+            # and not csv (containing PII) provided by the user, so allow verify_code to continue to exist
+            if notification is None:
+                continue
+            if "verify_code" in str(notification.personalisation):
+                pass
+            else:
                 batch.append(notification)
     try:
         dao_batch_insert_notifications(batch)
diff --git a/app/clients/pinpoint/aws_pinpoint.py b/app/clients/pinpoint/aws_pinpoint.py
@@ -39,7 +39,7 @@ def validate_phone_number(self, country_code, phone_number):
             current_app.logger.info(hilite(response))
         except ClientError:
             current_app.logger.exception(
-                "#validate-phone-number Could not validate with pinpoint"
+                "#notify-debug-validate-phone-number Could not validate with pinpoint"
             )
 
         # TODO This is the structure of the response.  When the phone validation
diff --git a/app/clients/sms/aws_sns.py b/app/clients/sms/aws_sns.py
@@ -68,15 +68,16 @@ def send_sms(self, to, content, reference, sender=None, international=False):
                 non_scrubbable = " ".join(sender)
 
                 self.current_app.logger.info(
-                    f"notify-api-1385 sender {non_scrubbable} is a {type(sender)} default is a {type(default_num)}"
+                    f"notify-debug-api-1385 sender {non_scrubbable} is a {type(sender)} \
+                        default is a {type(default_num)}"
                 )
             else:
                 self.current_app.logger.warning(
-                    f"notify-api-1385 sender is type {type(sender)}!! {sender}"
+                    f"notify-debug-api-1385 sender is type {type(sender)}!! {sender}"
                 )
             if self._valid_sender_number(sender):
                 self.current_app.logger.info(
-                    f"notify-api-1385 use valid sender {non_scrubbable} instead of default {default_num}"
+                    f"notify-debug-api-1385 use valid sender {non_scrubbable} instead of default {default_num}"
                 )
 
                 attributes["AWS.MM.SMS.OriginationNumber"] = {
@@ -85,7 +86,7 @@ def send_sms(self, to, content, reference, sender=None, international=False):
                 }
             else:
                 self.current_app.logger.info(
-                    f"notify-api-1385 use default {default_num} instead of invalid sender"
+                    f"notify-debug-api-1385 use default {default_num} instead of invalid sender"
                 )
 
                 attributes["AWS.MM.SMS.OriginationNumber"] = {
diff --git a/app/dao/jobs_dao.py b/app/dao/jobs_dao.py
@@ -158,17 +158,17 @@ def dao_create_job(job):
     now_time = utc_now()
     diff_time = now_time - orig_time
     current_app.logger.info(
-        f"#notify-admin-1859 dao_create_job orig created at {orig_time} and now {now_time}"
+        f"#notify-debug-admin-1859 dao_create_job orig created at {orig_time} and now {now_time}"
     )
     if diff_time.total_seconds() > 300:  # It should be only a few seconds diff at most
         current_app.logger.error(
-            "#notify-admin-1859 Something is wrong with job.created_at!"
+            "#notify-debug-admin-1859 Something is wrong with job.created_at!"
         )
         if os.getenv("NOTIFY_ENVIRONMENT") not in ["test"]:
             job.created_at = now_time
             dao_update_job(job)
             current_app.logger.error(
-                f"#notify-admin-1859 Job created_at reset to {job.created_at}"
+                f"#notify-debug-admin-1859 Job created_at reset to {job.created_at}"
             )
 
 
diff --git a/app/delivery/send_to_providers.py b/app/delivery/send_to_providers.py
@@ -42,12 +42,14 @@ def send_sms_to_provider(notification):
     """
     # Take this path for report generation, where we know
     # everything is in the cache.
-    personalisation = get_personalisation_from_s3(
-        notification.service_id,
-        notification.job_id,
-        notification.job_row_number,
-    )
-    notification.personalisation = personalisation
+
+    if "verify_code" not in str(notification.personalisation):
+        personalisation = get_personalisation_from_s3(
+            notification.service_id,
+            notification.job_id,
+            notification.job_row_number,
+        )
+        notification.personalisation = personalisation
 
     service = SerialisedService.from_id(notification.service_id)
     message_id = None
@@ -92,7 +94,6 @@ def send_sms_to_provider(notification):
                 recipient = None
                 # It is our 2facode, maybe
                 recipient = _get_verify_code(notification)
-
                 if recipient is None:
                     recipient = get_phone_number_from_s3(
                         notification.service_id,
@@ -107,7 +108,7 @@ def send_sms_to_provider(notification):
                 sender_numbers = get_sender_numbers(notification)
                 if notification.reply_to_text not in sender_numbers:
                     raise ValueError(
-                        f"{notification.reply_to_text} not in {sender_numbers} #notify-admin-1701"
+                        f"{notification.reply_to_text} not in {sender_numbers} #notify-debug-admin-1701"
                     )
 
                 send_sms_kwargs = {
@@ -158,7 +159,7 @@ def _experimentally_validate_phone_numbers(recipient):
     if recipient_lookup in current_app.config["SIMULATED_SMS_NUMBERS"] and os.getenv(
         "NOTIFY_ENVIRONMENT"
     ) in ["development", "test"]:
-        current_app.logger.info(hilite("#validate-phone-number fired"))
+        current_app.logger.info(hilite("#notify-debug-validate-phone-number fired"))
         aws_pinpoint_client.validate_phone_number("01", recipient)
 
 
diff --git a/app/job/rest.py b/app/job/rest.py
@@ -242,7 +242,9 @@ def create_job(service_id):
     original_file_name = data.get("original_file_name")
     data.update({"service": service_id})
     try:
-        current_app.logger.info(f"#s3-partitioning DATA IN CREATE_JOB: {data}")
+        current_app.logger.info(
+            f"#notify-debug-s3-partitioning DATA IN CREATE_JOB: {data}"
+        )
         data.update(**get_job_metadata_from_s3(service_id, data["id"]))
     except KeyError:
         raise InvalidRequest(
diff --git a/app/models.py b/app/models.py
@@ -1709,7 +1709,7 @@ def serialize_for_redis(self, obj):
                         value = (obj.created_at.strftime("%Y-%m-%d %H:%M:%S"),)
                 elif column.name in ["sent_at", "completed_at"]:
                     value = None
-                elif column.name.endswith("_id"):
+                elif column.name.endswith("_id") or column.name == "id":
                     value = getattr(obj, column.name)
                     value = str(value)
                 else:
diff --git a/app/notifications/process_notifications.py b/app/notifications/process_notifications.py
@@ -145,6 +145,9 @@ def persist_notification(
             # it's just too hard with redis and timing to test this here
             if os.getenv("NOTIFY_ENVIRONMENT") == "test":
                 dao_create_notification(notification)
+            elif "verify_code" in str(notification.personalisation):
+                dao_create_notification(notification)
+
             else:
                 redis_store.rpush(
                     "message_queue",
diff --git a/docs/adrs/0013-log-debug-tags.md b/docs/adrs/0013-log-debug-tags.md
@@ -0,0 +1,38 @@
+# Use of debug search tags for cloudwatch logs
+
+Status: Accepted
+Date: 27 February 2025
+
+### Context
+
+We encountered some recurrent problems in specific parts of the code that re-occurred regularly.
+
+We found it hard to debug these issues searching through cloudwatch logs as a particular issue
+tends to be exploded into multiple log lines, and these lines are not even time sorted by default
+so it can get quite hard on the eyes and test one's patience to debug this way.
+
+### Decision
+
+We decided to start using unique tags for individual issues so we could quickly search for related
+groups of log lines.  This worked fairly well and even though some of these issues at long last
+have been resolved, it might be worthwhile to continue this debugging pattern.
+
+### Consequences
+
+Here are the existing tags and what they are used for:
+
+#notify-debug-admin-1200: job cache regeneration
+#notify-debug-admin-1701: wrong sender phone number
+#notify-debug-admin-1859: job creation time reset due to strange SqlAlchemy constructor issue setting wrong created_at time
+#notify-debug-api-1385: a separate identify to resolve the wrong sender phone number issue
+#notify-debug-s3-partitioning: modify s3 partitioning in line with best aws practices
+#notify-debug-validate-phone-number: experimental code to try to validate phone numbers with aws pinpoint
+
+
+
+
+### Author
+@kenkehl
+
+### Stakeholders
+@ccostino
diff --git a/poetry.lock b/poetry.lock
diff --git a/pyproject.toml b/pyproject.toml
diff --git a/tests/app/aws/test_s3.py b/tests/app/aws/test_s3.py
diff --git a/tests/app/celery/test_scheduled_tasks.py b/tests/app/celery/test_scheduled_tasks.py

Original file line number	Diff line number	Diff line change
`@@ -39,7 +39,7 @@ def validate_phone_number(self, country_code, phone_number):`
`39`	`39`	`current_app.logger.info(hilite(response))`
`40`	`40`	`except ClientError:`
`41`	`41`	`current_app.logger.exception(`
`42`		`- "#validate-phone-number Could not validate with pinpoint"`
	`42`	`+ "#notify-debug-validate-phone-number Could not validate with pinpoint"`
`43`	`43`	`)`
`44`	`44`
`45`	`45`	`# TODO This is the structure of the response. When the phone validation`
Original file line number	Diff line number	Diff line change
`@@ -68,15 +68,16 @@ def send_sms(self, to, content, reference, sender=None, international=False):`
`68`	`68`	`non_scrubbable = " ".join(sender)`
`69`	`69`
`70`	`70`	`self.current_app.logger.info(`
`71`		`- f"notify-api-1385 sender {non_scrubbable} is a {type(sender)} default is a {type(default_num)}"`
	`71`	`+ f"notify-debug-api-1385 sender {non_scrubbable} is a {type(sender)} \`
	`72`	`+ default is a {type(default_num)}"`
`72`	`73`	`)`
`73`	`74`	`else:`
`74`	`75`	`self.current_app.logger.warning(`
`75`		`- f"notify-api-1385 sender is type {type(sender)}!! {sender}"`
	`76`	`+ f"notify-debug-api-1385 sender is type {type(sender)}!! {sender}"`
`76`	`77`	`)`
`77`	`78`	`if self._valid_sender_number(sender):`
`78`	`79`	`self.current_app.logger.info(`
`79`		`- f"notify-api-1385 use valid sender {non_scrubbable} instead of default {default_num}"`
	`80`	`+ f"notify-debug-api-1385 use valid sender {non_scrubbable} instead of default {default_num}"`
`80`	`81`	`)`
`81`	`82`
`82`	`83`	`attributes["AWS.MM.SMS.OriginationNumber"] = {`
`@@ -85,7 +86,7 @@ def send_sms(self, to, content, reference, sender=None, international=False):`
`85`	`86`	`}`
`86`	`87`	`else:`
`87`	`88`	`self.current_app.logger.info(`
`88`		`- f"notify-api-1385 use default {default_num} instead of invalid sender"`
	`89`	`+ f"notify-debug-api-1385 use default {default_num} instead of invalid sender"`
`89`	`90`	`)`
`90`	`91`
`91`	`92`	`attributes["AWS.MM.SMS.OriginationNumber"] = {`
Original file line number	Diff line number	Diff line change
`@@ -158,17 +158,17 @@ def dao_create_job(job):`
`158`	`158`	`now_time = utc_now()`
`159`	`159`	`diff_time = now_time - orig_time`
`160`	`160`	`current_app.logger.info(`
`161`		`- f"#notify-admin-1859 dao_create_job orig created at {orig_time} and now {now_time}"`
	`161`	`+ f"#notify-debug-admin-1859 dao_create_job orig created at {orig_time} and now {now_time}"`
`162`	`162`	`)`
`163`	`163`	`if diff_time.total_seconds() > 300: # It should be only a few seconds diff at most`
`164`	`164`	`current_app.logger.error(`
`165`		`- "#notify-admin-1859 Something is wrong with job.created_at!"`
	`165`	`+ "#notify-debug-admin-1859 Something is wrong with job.created_at!"`
`166`	`166`	`)`
`167`	`167`	`if os.getenv("NOTIFY_ENVIRONMENT") not in ["test"]:`
`168`	`168`	`job.created_at = now_time`
`169`	`169`	`dao_update_job(job)`
`170`	`170`	`current_app.logger.error(`
`171`		`- f"#notify-admin-1859 Job created_at reset to {job.created_at}"`
	`171`	`+ f"#notify-debug-admin-1859 Job created_at reset to {job.created_at}"`
`172`	`172`	`)`
`173`	`173`
`174`	`174`